You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "tupelo-schneck (via GitHub)" <gi...@apache.org> on 2026/07/28 22:43:47 UTC
[PR] Fix multi-second startup delay in CronTriggeringPolicy [logging-log4j2]
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "ramanathan1504 (via GitHub)" <gi...@apache.org>.
ramanathan1504 commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3877932022
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DirectWriteRolloverStrategy.java:
##########
@@ -390,8 +390,10 @@ public String getCurrentFileName(final RollingFileManager manager) {
final SortedMap<Integer, Path> eligibleFiles = getEligibleFiles(manager);
final int fileIndex = eligibleFiles.size() > 0 ? (nextIndex > 0 ? nextIndex : eligibleFiles.lastKey()) : 1;
final StringBuilder buf = new StringBuilder(255);
- // LOG4J2-3339 - Always use the current time for new direct write files.
- manager.getPatternProcessor().setCurrentFileTime(System.currentTimeMillis());
+ // Name the file after the start of the rollover period it belongs to, which the
+ // triggering policy records as the pattern processor's current file time. Policies
+ // that do not track a period leave that value at 0, and `formatFileName()` then
+ // falls back to the current time on its own.
Review Comment:
```suggestion
```
no need here
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix multi-second startup delay in CronTriggeringPolicy [logging-log4j2]
Posted by "ramanathan1504 (via GitHub)" <gi...@apache.org>.
ramanathan1504 commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3851394450
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java:
##########
@@ -64,7 +64,11 @@ private CronTriggeringPolicy(
public void initialize(final RollingFileManager aManager) {
this.manager = aManager;
final Date now = new Date();
- final Date lastRollForFile = cronExpression.getPrevFireTime(new Date(this.manager.getFileTime()));
+ // `RollingFileManager` reports a file time of 0 when there is no current file yet, which
+ // happens on every startup of an appender configured without a `fileName`. There is no
+ // previous roll to look up in that case, so skip the lookup entirely.
+ final long fileTime = this.manager.getFileTime();
Review Comment:
`testBuilderWithoutFileNameInitializesPromptly` passes with either fix alone (0.134 s / 0.143 s) and fails only when both are reverted, so nothing pins this guard — is it load-bearing, or documentation like `TimeBasedTriggeringPolicy.initialize()`'s `getFileTime() == 0`?
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/util/CronExpression.java:
##########
@@ -1581,6 +1581,13 @@ protected Date getTimeBefore(final Date targetDate) {
Date prevFireTime;
do {
final Date prevCheckDate = new Date(start.getTime() - minIncrement);
+ // `getTimeAfter()` never returns a fire time before 1970, so once the candidate
+ // date precedes `MIN_DATE` the loop condition below can no longer be satisfied.
+ // Bail out here, otherwise the search walks back millennia one increment at a
+ // time before `getTimeAfter()` finally gives up at the calendar's upper bound.
+ if (prevCheckDate.before(MIN_DATE)) {
+ return null;
+ }
Review Comment:
`MIN_CAL.set(1970, 0, 1)` never clears the time fields, so `MIN_DATE` carries the JVM's start time of day — I printed `12:01:08.151`, `12:03:05.302` and `12:01:39.611` across three runs.
That only mattered once this guard started bounding the *candidate*: with `0 0 0 * * ?`, `getPrevFireTime(1970-01-02 06:00)` gives `1970-01-02 00:00:00` on 2.x and `null` here. Bounding on the epoch is deterministic — verified green plus spotless.
````suggestion
// `getTimeAfter()` never returns a fire time before 1970, so once the candidate
// date precedes the epoch the loop condition below can no longer be satisfied.
// Bail out here, otherwise the search walks back millennia one increment at a
// time before `getTimeAfter()` finally gives up at the calendar's upper bound.
if (prevCheckDate.getTime() < 0) {
return null;
}
````
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "tupelo-schneck (via GitHub)" <gi...@apache.org>.
tupelo-schneck commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3880607242
##########
log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java:
##########
Review Comment:
Done
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "ramanathan1504 (via GitHub)" <gi...@apache.org>.
ramanathan1504 commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3877937652
##########
log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicyTest.java:
##########
Review Comment:
Remove Javadoc comments and inline comments
##########
log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java:
##########
Review Comment:
Remove inline and Javadoc things
##########
src/changelog/.2.x.x/fix_cron_triggering_policy_slow_startup.xml:
##########
@@ -0,0 +1,14 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns="https://logging.apache.org/xml/ns"
+ xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+ xsi:schemaLocation="
+ https://logging.apache.org/xml/ns
+ https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+ type="fixed">
+ <issue id="4226" link="https://github.com/apache/logging-log4j2/pull/4226"/>
+ <description format="asciidoc">
+ Fix a multi-second startup delay in `CronTriggeringPolicy` for appenders configured without a `fileName`.
+ `CronExpression.getPrevFireTime()` now bounds its backward search at 1970 instead of scanning millennia of
+ candidate dates before returning `null`.
Review Comment:
```suggestion
Changes `CronTriggeringPolicy` startup delay and name its direct write files after the rollover period.
```
##########
src/changelog/.2.x.x/fix_cron_triggering_policy_slow_startup.xml:
##########
@@ -0,0 +1,14 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns="https://logging.apache.org/xml/ns"
+ xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+ xsi:schemaLocation="
+ https://logging.apache.org/xml/ns
+ https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+ type="fixed">
Review Comment:
```suggestion
type="changed">
```
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "tupelo-schneck (via GitHub)" <gi...@apache.org>.
tupelo-schneck commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3880605198
##########
log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicyTest.java:
##########
Review Comment:
Done
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "ramanathan1504 (via GitHub)" <gi...@apache.org>.
ramanathan1504 commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3877932022
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DirectWriteRolloverStrategy.java:
##########
@@ -390,8 +390,10 @@ public String getCurrentFileName(final RollingFileManager manager) {
final SortedMap<Integer, Path> eligibleFiles = getEligibleFiles(manager);
final int fileIndex = eligibleFiles.size() > 0 ? (nextIndex > 0 ? nextIndex : eligibleFiles.lastKey()) : 1;
final StringBuilder buf = new StringBuilder(255);
- // LOG4J2-3339 - Always use the current time for new direct write files.
- manager.getPatternProcessor().setCurrentFileTime(System.currentTimeMillis());
+ // Name the file after the start of the rollover period it belongs to, which the
+ // triggering policy records as the pattern processor's current file time. Policies
+ // that do not track a period leave that value at 0, and `formatFileName()` then
+ // falls back to the current time on its own.
Review Comment:
```suggestion
```
no need
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "tupelo-schneck (via GitHub)" <gi...@apache.org>.
tupelo-schneck commented on PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#issuecomment-5411817913
Thanks for reviewing both — consolidated as you asked.
#4227's change is now here as 79037d369, and I have closed #4227 pointing at this PR. The description is rewritten to cover both fixes, and the two changelog entries now both reference this one.
Briefly, on the second fix, since it arrived without its own discussion: a direct write file was being named after the moment the appender started rather than after the rollover period it covers, so a restart later in the period opened a second file for a period meant to have one. Under a weekly schedule with a `%d{yyyyMMdd}` pattern, a week of daily restarts leaves seven files instead of one. Fixing it partly unwinds LOG4J2-3339 and changes direct write file names for cron based appenders, so it is worth a look on its own terms — the reasoning and the compatibility note are in the description.
`./mvnw verify` passes on the combined branch across all 41 modules.
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "tupelo-schneck (via GitHub)" <gi...@apache.org>.
tupelo-schneck commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3853936165
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/util/CronExpression.java:
##########
@@ -1581,6 +1581,13 @@ protected Date getTimeBefore(final Date targetDate) {
Date prevFireTime;
do {
final Date prevCheckDate = new Date(start.getTime() - minIncrement);
+ // `getTimeAfter()` never returns a fire time before 1970, so once the candidate
+ // date precedes `MIN_DATE` the loop condition below can no longer be satisfied.
+ // Bail out here, otherwise the search walks back millennia one increment at a
+ // time before `getTimeAfter()` finally gives up at the calendar's upper bound.
+ if (prevCheckDate.before(MIN_DATE)) {
+ return null;
+ }
Review Comment:
Applied, thank you — this is a real defect in what I wrote, not a style preference.
I reproduced the nondeterminism: two JVMs started seconds apart print `MIN_DATE` as `09:40:09` and `09:40:17`, since `MIN_CAL.set(1970, 0, 1)` leaves the time fields alone. Your example reproduces exactly — for `0 0 0 * * ?` at `1970-01-02 06:00`, `2.x` returns `1970-01-02 00:00` where the `MIN_DATE` bound returned `null`. A correct answer silently replaced, and which answer you got depended on when the process started.
I also tried bounding on the local 1970 instant in the expression's own zone, on the theory that `getTime() < 0` is a UTC instant test while `getTimeAfter()` floors at local 1970. Across `America/New_York`, `UTC` and `Australia/Sydney` it produced results identical to the epoch bound on every case I tried, so the simpler form is the right one.
Added `testPrevFireTimeJustAfterEpochIsUnaffectedByBound` to pin this — it fails with the `MIN_DATE` bound and passes with the epoch, in a fixed zone so it does not depend on the CI host.
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "ramanathan1504 (via GitHub)" <gi...@apache.org>.
ramanathan1504 commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3877932022
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DirectWriteRolloverStrategy.java:
##########
@@ -390,8 +390,10 @@ public String getCurrentFileName(final RollingFileManager manager) {
final SortedMap<Integer, Path> eligibleFiles = getEligibleFiles(manager);
final int fileIndex = eligibleFiles.size() > 0 ? (nextIndex > 0 ? nextIndex : eligibleFiles.lastKey()) : 1;
final StringBuilder buf = new StringBuilder(255);
- // LOG4J2-3339 - Always use the current time for new direct write files.
- manager.getPatternProcessor().setCurrentFileTime(System.currentTimeMillis());
+ // Name the file after the start of the rollover period it belongs to, which the
+ // triggering policy records as the pattern processor's current file time. Policies
+ // that do not track a period leave that value at 0, and `formatFileName()` then
+ // falls back to the current time on its own.
Review Comment:
```suggestion
```
no need
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "tupelo-schneck (via GitHub)" <gi...@apache.org>.
tupelo-schneck commented on code in PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226#discussion_r3853938753
##########
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java:
##########
@@ -64,7 +64,11 @@ private CronTriggeringPolicy(
public void initialize(final RollingFileManager aManager) {
this.manager = aManager;
final Date now = new Date();
- final Date lastRollForFile = cronExpression.getPrevFireTime(new Date(this.manager.getFileTime()));
+ // `RollingFileManager` reports a file time of 0 when there is no current file yet, which
+ // happens on every startup of an appender configured without a `fileName`. There is no
+ // previous roll to look up in that case, so skip the lookup entirely.
+ final long fileTime = this.manager.getFileTime();
Review Comment:
Documentation, not load-bearing — your second reading is right, and thank you for checking it rather than assuming.
I confirmed it: with the epoch bound in `CronExpression` in place and this guard reverted, `CronTriggeringPolicyTest` and `CronExpressionTest` pass in 0.18 s. Once the search is bounded, `getPrevFireTime(new Date(0))` returns `null` in microseconds for any expression, so nothing here depends on the guard for speed.
I have kept it, for the reason you name: it mirrors `TimeBasedTriggeringPolicy.initialize()`'s `getFileTime() == 0` check, and it makes `lastRollForFile` `null` by construction rather than by a lookup that happens to return `null` for a meaningless input. Happy to drop it if you would rather keep the diff minimal — no functional difference either way.
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix startup delay and direct write file naming in CronTriggeringPolicy [logging-log4j2]
Posted by "ramanathan1504 (via GitHub)" <gi...@apache.org>.
ramanathan1504 merged PR #4226:
URL: https://github.com/apache/logging-log4j2/pull/4226
--
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: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org