Skip to content

Stop boxing a Long per cache miss in the instant formatting cache - #4322

Open
Myllyenko wants to merge 2 commits into
apache:2.xfrom
Myllyenko:perf/instant-formatter-boxing
Open

Myllyenko wants to merge 2 commits into
apache:2.xfrom
Myllyenko:perf/instant-formatter-boxing

Conversation

@Myllyenko

Copy link
Copy Markdown

InstantPatternThreadLocalCachedFormatter keyed its per-thread cache on a Long: the epoch instant was extracted through a Function<Instant, Long> and stored, boxed, into an Object[] held in a ThreadLocal. Both extractors, Instant::getEpochMillisecond and Instant::getEpochSecond, return a primitive, and epoch values are far outside the Long cache.

The extractor's box turns out to be scalar-replaced on a cache hit, since it is unboxed straight into a local and never escapes. The box stored into the Object[] does escape, so every cache miss allocated. A miss happens once per distinct instant per thread, which for any thread logging at under a thousand events per second is every single event.

Replace the extractor with a ToLongFunction<Instant> and the Object[] with a small holder carrying a primitive long field next to the buffer. StringBuilderEncoder documents a preference for keeping only JDK types in thread locals, to avoid pinning a class loader in a web container, but that does not apply here: this wrapper is only installed when Constants.ENABLE_THREADLOCALS is set, and that flag is off for web applications precisely to disable the thread locals which could leak.

Measured with the JMH benchmark added here, 1000 instants per operation:

                    before                 after
cacheMiss   24000.152 B/op, 153 GCs    0.141 B/op, no GC
cacheMiss    21744 +- 2404 ns/op       20274 +- 406 ns/op
cacheHit         0.038 B/op              0.040 B/op
cacheHit      5410 +- 70 ns/op          5696 +- 699 ns/op

Also close a cache-poisoning window while here: the cached epoch instant is now cleared before the buffer is rewritten and restored only once formatting succeeds, so a throwing formatter can no longer leave a later call reading a half-written buffer. Note that merely moving the assignment after the formatting does not fix this; it only changes which instant triggers it.

INSERT HERE a clear and concise description of what the pull request is for along with a reference to the associated issue IDs, if they exist.

`InstantPatternThreadLocalCachedFormatter` keyed its per-thread cache on a
`Long`: the epoch instant was extracted through a `Function<Instant, Long>`
and stored, boxed, into an `Object[]` held in a `ThreadLocal`. Both extractors,
`Instant::getEpochMillisecond` and `Instant::getEpochSecond`, return a
primitive, and epoch values are far outside the `Long` cache.

The extractor's box turns out to be scalar-replaced on a cache hit, since it
is unboxed straight into a local and never escapes. The box stored into the
`Object[]` does escape, so every cache miss allocated. A miss happens once per
distinct instant per thread, which for any thread logging at under a thousand
events per second is every single event.

Replace the extractor with a `ToLongFunction<Instant>` and the `Object[]` with
a small holder carrying a primitive `long` field next to the buffer.
`StringBuilderEncoder` documents a preference for keeping only JDK types in
thread locals, to avoid pinning a class loader in a web container, but that
does not apply here: this wrapper is only installed when
`Constants.ENABLE_THREADLOCALS` is set, and that flag is off for web
applications precisely to disable the thread locals which could leak.

Measured with the JMH benchmark added here, 1000 instants per operation:

                        before                 after
    cacheMiss   24000.152 B/op, 153 GCs    0.141 B/op, no GC
    cacheMiss    21744 +- 2404 ns/op       20274 +- 406 ns/op
    cacheHit         0.038 B/op              0.040 B/op
    cacheHit      5410 +- 70 ns/op          5696 +- 699 ns/op

Also close a cache-poisoning window while here: the cached epoch instant is
now cleared before the buffer is rewritten and restored only once formatting
succeeds, so a throwing formatter can no longer leave a later call reading a
half-written buffer. Note that merely moving the assignment after the
formatting does not fix this; it only changes which instant triggers it.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@vy vy self-assigned this Sep 16, 2026
@vy vy added enhancement Additions or updates to features performance Issues or PRs that affect performance, throughput, latency, etc. layouts Affects one or more Layout plugins labels Sep 16, 2026

@vy vy left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This [seemingly AI-generated] content will need some review. I'm not very keen on adding yet another ThreadLocal to Log4j's event rendering pipeline. Allow me some time, please.

@github-project-automation github-project-automation Bot moved this to Changes requested in Log4j pull request tracker Sep 16, 2026
@vy vy added the vy label Sep 16, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement Additions or updates to features layouts Affects one or more Layout plugins performance Issues or PRs that affect performance, throughput, latency, etc. vy

Projects

Status: Changes requested

Development

Successfully merging this pull request may close these issues.

3 participants