[LOG4J2-1339] AsyncLogger should not call instanceof TimestampMessage in hot path

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0.1, 2.0.2, 2.1, 2.2, 2.3, 2.4, 2.4.1, 2.5
• Fix Version/s: 2.6
• Component/s: Core
• Assignee: Remko Popma
• Reporter: Remko Popma
• Created: 30/Mar/16 14:32
• Updated: 30/Mar/16 15:23
• Resolved: 30/Mar/16 15:23

Description

With LOG4J2-744, AsyncLogger attempts to get the time from the message by calling

millis = message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() : CLOCK.currentTimeMillis()

for every message. The vast majority of messages are not TimestampMessages so the time is eventually obtained from the clock. However, benchmarking shows that the instanceof check is not free.

It gives better performance (especially for simple fixed text log messages) to postpone the above logic to the background thread.

Before:

java -Dlog4j2.enable.threadlocals=false -DAsyncLogger.RingBufferSize=262144  -jar benchmarks-2.6-varargs20160329.jar ".AsyncLoggersBench.*" -f 1 -wi 5 -i 10
Benchmark                                                Mode  Samples        Score        Error  Units
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput3Params     thrpt       10  2536721.716 ± 346845.032  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput5Params     thrpt       10  2177187.778 ± 305779.317  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput7Params     thrpt       10  1749921.199 ± 274752.264  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput9Params     thrpt       10  1621232.163 ± 213933.235  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughputSimple      thrpt       10  4734890.484 ± 495169.073  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.latency3Params       sample   114628      401.673 ±      8.308  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latency5Params       sample    92326      491.471 ±     10.322  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latency7Params       sample   152204      583.759 ±      2.475  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latency9Params       sample   134818      658.336 ±     10.086  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latencySimple        sample   121357      264.867 ±      1.879  ns/op

After:

java -Dlog4j2.enable.threadlocals=false -DAsyncLogger.RingBufferSize=262144  -jar benchmarks-2.6-varargs20160330Tm.jar ".AsyncLoggersBench.*" -f 1 -wi 5 -i 10
Benchmark                                                Mode  Samples        Score        Error  Units
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput3Params     thrpt       10  3024631.638 ± 603690.008  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput5Params     thrpt       10  2075676.591 ± 565118.526  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput7Params     thrpt       10  1941322.235 ± 294362.669  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughput9Params     thrpt       10  1731353.147 ± 292176.130  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.throughputSimple      thrpt       10  5247737.873 ± 498790.784  ops/s
o.a.l.l.p.j.AsyncLoggersBenchmark.latency3Params       sample   136170      333.617 ±      8.183  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latency5Params       sample   108236      496.328 ±      2.497  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latency7Params       sample   144521      632.009 ±      2.825  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latency9Params       sample   137998      776.229 ±    433.813  ns/op
o.a.l.l.p.j.AsyncLoggersBenchmark.latencySimple        sample   106458      234.457 ±      8.377  ns/op

Issue Links

• supercedes: LOG4J2-744 Avoid unnecessary Clock calls when TimestampMessage is logged