[prev in list] [next in list] [prev in thread] [next in thread]
List: log4j-dev
Subject: [jira] [Updated] (LOG4J2-1339) AsyncLogger should not call instanceof TimestampMessage in hot path
From: "Remko Popma (JIRA)" <jira () apache ! org>
Date: 2016-03-30 15:23:25
Message-ID: JIRA.12954648.1459348353000.89094.1459351405597 () Atlassian ! JIRA
[Download RAW message or body]
[ 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
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic