Skip to content

Fix multi-second startup delay in CronTriggeringPolicy - #4226

Open
tupelo-schneck wants to merge 2 commits into
apache:2.xfrom
tupelo-schneck:fix/cron-triggering-policy-slow-startup
Open

Fix multi-second startup delay in CronTriggeringPolicy#4226
tupelo-schneck wants to merge 2 commits into
apache:2.xfrom
tupelo-schneck:fix/cron-triggering-policy-slow-startup

Conversation

@tupelo-schneck

Copy link
Copy Markdown

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():

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:

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:

<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

  • Based on 2.x
  • ./mvnw verify succeeds
  • Changelog entry in src/changelog/.2.x.x
  • Tests are provided

`CronTriggeringPolicy.initialize()` looks up the previous fire time relative
to `RollingFileManager#getFileTime()`. That value is 0 whenever there is no
current file yet, which is the case on every startup of an appender configured
without a `fileName`. The resulting `getPrevFireTime(new Date(0))` call took
roughly three seconds per appender.

`CronExpression.getTimeBefore()` walks backwards from the target date one
`findMinIncrement()` step at a time, calling `getTimeAfter()` until the result
precedes the target. `getTimeAfter()` clamps its result to 1970, so for a
target at the epoch that exit condition can never be satisfied and the search
instead grinds back through several millennia of candidate dates before
`getTimeAfter()` finally gives up and the method returns `null`.

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.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Development

Successfully merging this pull request may close these issues.

1 participant