logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (LOG4J2-1339) AsyncLogger should not call instanceof TimestampMessage in hot path
Date Wed, 30 Mar 2016 15:23:25 GMT

     [ 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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message