Fix multi-second startup delay in CronTriggeringPolicy - #4226
Open
tupelo-schneck wants to merge 2 commits into
Open
Fix multi-second startup delay in CronTriggeringPolicy#4226tupelo-schneck wants to merge 2 commits into
tupelo-schneck wants to merge 2 commits into
Conversation
`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>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
CronTriggeringPolicy.initialize()spends roughly three seconds per appender on startup for any appender configured without afileName. A configuration with two such appenders takes about six seconds to initialise logging.Cause
initialize()looks up the previous fire time relative toRollingFileManager#getFileTime():RollingFileManagerreports 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 onefindMinIncrement()step at a time, callinggetTimeAfter()until the result precedes the target: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 neithernull, nor beforeMIN_DATE, nor before the target. The search walks back through several millennia of candidate dates until the calendar's era flips andgetTimeAfter()finally bails out at itsYEAR > 2999guard, and the method returnsnull.A stack sample from an affected startup, taken once a second, showing the main thread pinned at 100% CPU for the duration:
Reproduced with:
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 thatevaluateOnStartup="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 returnednullfor this input, so behaviour is unchanged; only the cost differs.getPrevFireTime(new Date(0))for0 0 0 ? * SUN, measured against this branch'sCronExpression: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.xwithout the fix and pass with it:CronExpressionTest#testPrevFireTimeAtEpochReturnsNullPromptly— assertsnullwithin 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 afileNameon a weekly schedule../mvnw verifypasses across all 41 modules: 11089 tests, 0 failures, 0 errors, 40 pre-existing environment-conditional skips.Checklist
2.x./mvnw verifysucceedssrc/changelog/.2.x.x