[
https://issues.apache.org/jira/browse/LOG4J2-1339?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma updated LOG4J2-1339:
--------------------------------
Description:
With LOG4J2-744, AsyncLogger attempts to get the time from the message by
calling
{code}
millis = message instanceof TimestampMessage ? ((TimestampMessage)
message).getTimestamp() : CLOCK.currentTimeMillis()
{code}
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:
{noformat}
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
{noformat}
After:
{noformat}
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
{noformat}
was:
With LOG4J2-744, AsyncLogger attempts to get the time from the message by
calling
{code}
millis = message instanceof TimestampMessage ? ((TimestampMessage)
message).getTimestamp() : CLOCK.currentTimeMillis()
{code}
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 to postpone the above logic to the background
thread.
> AsyncLogger should not call instanceof TimestampMessage in hot path
> -------------------------------------------------------------------
>
> Key: LOG4J2-1339
> URL: https://issues.apache.org/jira/browse/LOG4J2-1339
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.1, 2.0.2, 2.1, 2.2, 2.3, 2.4, 2.4.1, 2.5
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.6
>
>
> With LOG4J2-744, AsyncLogger attempts to get the time from the message by
> calling
> {code}
> millis = message instanceof TimestampMessage ? ((TimestampMessage)
> message).getTimestamp() : CLOCK.currentTimeMillis()
> {code}
> 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:
> {noformat}
> 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
> {noformat}
> After:
> {noformat}
> 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
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
