Remove garbage creation introduced by LOG4J2-2301

[mprusakov-rbc]

After upgrading to 2.11.1 we have started seeing garbage being generated here:

Stack Trace TLABs Total TLAB Size(bytes) Pressure(%)
java.lang.ThreadLocal$ThreadLocalMap.set(ThreadLocal, Object) line: 481 10 3,638,864 56.192
java.lang.ThreadLocal$ThreadLocalMap.access$100(ThreadLocal$ThreadLocalMap, ThreadLocal, Object) line: 298 10 3,638,864 56.192
java.lang.ThreadLocal.setInitialValue() line: 184 10 3,638,864 56.192
java.lang.ThreadLocal.get() line: 170 10 3,638,864 56.192
org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(LogEvent, LoggerConfig$LoggerConfigPredicate) line: 91 10 3,638,864 56.192

The purpose of this patch is to fix this.

[carterkozak]

Thank you for reporting! I'm surprised that this wasn't caught by GcFreeMixedSyncAyncLoggingTest, we should fix the bug which allowed this regression to occur.

[remkop]

Yes, that is worrisome. Would be great if we can make the test fail, to confirm that the patch fixes the issue.

[garydgregory]

+1 having a failing test, otherwise we are almost guaranteeing the regression will come back :-( Gary

…

On Fri, Jan 11, 2019 at 6:31 PM Remko Popma ***@***.***> wrote: Yes, that is worrisome. Would be great if we can make the test fail, to confirm that the patch fixes the issue. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#251 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABIfN4vuFk-79n0rIecPS7mW7XnidjJSks5vCR7rgaJpZM4Z76KQ> .

[carterkozak]

This issue is a bit difficult to test for because it requires several threads to log. There's allocation if a ThreadLocal set operation resizes the internal threadlocal map hash table.

[garydgregory]

Can't this be testing with a single thread? Maybe we need to add a package private methods to ease testing?

[mprusakov-rbc]

First of all, thank you for spending time looking at my patch,

I can confirm that I have tested it by patching this one file and allocations do disappear. Taking in account that the build has passed I have every confidence that the patch works.

Frankly, I wasn't aware of the test mentioned above. If defaults are used garbage does get generated even in 2.11.0 by the disruptor so i can look into creating a generic test but then i will have to change the defaults which i am sure people will generally be unhappy about as let's be honest there is very little Java developers who care about garbage...

Having said that, would it be possible to submit this patch and tackle the test separately? Many thanks in advance.

[carterkozak]

Can't this be testing with a single thread?

I don't believe we can, the issue is that changes in ThreadLocal map size (which can only change by 1 on the current thread, which doesn't trigger the issue) result in allocation of new Entry objects if rehashing/expungeStaleEntry has nulled the current value after a hash collision.

would it be possible to submit this patch and tackle the test separately?

I would be okay with merging the fix before we put together a test (pending other devs agreement, of course) because:

1. The test will be significantly more complex than the issue
2. We understand why this is happening
3. I have audited the codebase for this pattern, and don't see other occurrences in gc-free code.

[jvz]

The @PerformanceSensitive annotation can be used to mark the code as something that should be looked at. We don't have any tooling around that annotation currently, but it's useful for catching regressions like this later on when modifying that code.

[remkop]

Carter, thanks for the clarification. I don’t object to merging the fix first.

[carterkozak]

I've filed this ticket for tracking: https://issues.apache.org/jira/browse/LOG4J2-2533

[carterkozak]

Thank you for your contribution @mprusakov-rbc!