tupelo-schneck opened a new pull request, #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226
`CronTriggeringPolicy.initialize()` spends roughly three seconds per
appender on startup for any appender configured without a `fileName`. A
configuration with two such appenders takes about six seconds to initialise
logging.
## Cause
`initialize()` looks up the previous fire time relative to
`RollingFileManager#getFileTime()`:
```java
final Date lastRollForFile = cronExpression.getPrevFireTime(new
Date(this.manager.getFileTime()));
```
`RollingFileManager` reports a file time of 0 when there is no current file
yet (`file == null || !file.exists() ? 0 : initialFileTime(file)`), which is
the case on every startup of an appender that writes directly to the file its
pattern resolves to. The lookup therefore runs against the epoch.
`CronExpression.getTimeBefore()` walks backwards from the target one
`findMinIncrement()` step at a time, calling `getTimeAfter()` until the result
precedes the target:
```java
do {
final Date prevCheckDate = new Date(start.getTime() - minIncrement);
prevFireTime = getTimeAfter(prevCheckDate);
if (prevFireTime == null || prevFireTime.before(MIN_DATE)) {
return null;
}
start = prevCheckDate;
} while (prevFireTime.compareTo(targetDateNoMs) >= 0);
```
`getTimeAfter()` clamps its result to 1970, because an expression without a
year field gets a year set starting at 1970 and the tail set lookup returns
that first entry for any earlier year. For a target at the epoch the loop
condition can therefore never be satisfied: every iteration returns the same
1970 fire time, which is neither `null`, nor before `MIN_DATE`, nor before the
target. The search walks back through several millennia of candidate dates
until the calendar's era flips and `getTimeAfter()` finally bails out at its
`YEAR > 2999` guard, and the method returns `null`.
A stack sample from an affected startup, taken once a second, showing the
main thread pinned at 100% CPU for the duration:
```
"main" #3 prio=5 os_prio=31 cpu=749.54ms elapsed=103.85s runnable
java.lang.Thread.State: RUNNABLE
at
org.apache.logging.log4j.core.util.CronExpression.getTimeAfter(CronExpression.java:1201)
at
org.apache.logging.log4j.core.util.CronExpression.getTimeBefore(CronExpression.java:1584)
at
org.apache.logging.log4j.core.util.CronExpression.getPrevFireTime(CronExpression.java:1594)
at
org.apache.logging.log4j.core.appender.rolling.CronTriggeringPolicy.initialize(CronTriggeringPolicy.java:67)
at
org.apache.logging.log4j.core.appender.rolling.RollingFileManager.initialize(RollingFileManager.java:246)
at
org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:164)
...
at
org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:311)
```
Reproduced with:
```xml
<RollingFile name="errorLogAppender"
filePattern="${LOG_DIR}/error.log-%d{yyyyMMdd}">
<PatternLayout pattern="%m%n"/>
<CronTriggeringPolicy schedule="0 0 0 ? * SUN" evaluateOnStartup="true"/>
</RollingFile>
```
A weekly schedule is the worst case, since `findMinIncrement()` returns a
day-sized step for it, but any schedule whose previous fire time cannot be
resolved against the epoch is affected. Note that `evaluateOnStartup="false"`
does not avoid the cost, because the lookup at line 67 runs unconditionally and
only its result is guarded by that flag.
## Fix
Bound the backward search at `MIN_DATE`, and skip the lookup entirely when
there is no current file. Both paths already returned `null` for this input, so
behaviour is unchanged; only the cost differs.
`getPrevFireTime(new Date(0))` for `0 0 0 ? * SUN`, measured against this
branch's `CronExpression`:
| | duration |
| --- | --- |
| before | 2854–3040 ms |
| after | 0.03–0.06 ms |
End to end, the two-appender configuration above goes from ~6.0 s to ~0.2 s
to initialise.
## Testing
Two regression tests are included. Both were confirmed to fail against `2.x`
without the fix and pass with it:
* `CronExpressionTest#testPrevFireTimeAtEpochReturnsNullPromptly` — asserts
`null` within a 1 s timeout. The timeout is deliberately set well below the
~2.9 s the unfixed path takes, since a generous timeout would pass with the
defect still present.
* `CronTriggeringPolicyTest#testBuilderWithoutFileNameInitializesPromptly` —
builds an appender without a `fileName` on a weekly schedule.
`./mvnw verify` passes across all 41 modules: 11089 tests, 0 failures, 0
errors, 40 pre-existing environment-conditional skips.
## Checklist
* [x] Based on `2.x`
* [x] `./mvnw verify` succeeds
* [x] Changelog entry in `src/changelog/.2.x.x`
* [x] Tests are provided
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
