[LOG4J2-1382] Performance regression in RewriteAppender

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.6
• Fix Version/s: 2.6
• Component/s: Appenders
• Assignee: Remko Popma
• Reporter: Remko Popma
• Created: 09/May/16 11:18
• Updated: 09/May/16 16:20
• Resolved: 09/May/16 16:20

Description

While working on LOG4J2-1179, I ran into these benchmark results:

Benchmark                                                         Mode  Samples           Score            Error  Units
o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderRewrite    thrpt        5    44263670.008 ±   17389305.070  ops/s
o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endRewrite     thrpt        5       37254.554 ±      16440.919  ops/s

In plain English: directly calling RewriteAppender.append(LogEvent) can do 44 million ops/sec, but when calling rewriteLogger.debug(msg) to invoke a logger that calls this appender, all of a sudden throughput drops to 37 thousand ops/sec. That's 1000x slower. Fishy...

Turns out that when rewriting the event we are now including caller location information (taking a snapshot of the stack and walking it). Ouch.

This is a regression caused by the garbage-free stuff. Rewriting the event makes a copy of the event and avoids calling LogEvent.getSource() only if the event is an instance of Log4jLogEvent, but now we are passing in MutableLogEvent.

The fix is to update Log4jLogEvent.Builder to also avoid calling getSource when copying from a MutableLogEvent.