[
https://issues.apache.org/jira/browse/LOG4J2-930?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14258905#comment-14258905
]
Remko Popma commented on LOG4J2-930:
------------------------------------
I double checked, and Logger name almost halves the throughput of
PatternLayout-based logging. Precision has relatively small impact. I don't
know what causes this yet.
||%m%n||%c %m%n||%c{1.} %m%n||
|1,879,431| 978,239|903,658|
|1,900,177|1,008,326|906,213|
|1,839,971| 996,563|914,218|
|1,908,335|1,013,434|891,999|
|1,893,475|1,042,245|890,328|
|1,903,774| 984,005|905,389|
_(These performance tests and the ones above were all *single-threaded*, done
on Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU @2.93Ghz
with hyperthreading switched on (16 virtual cores), using the classes in the
{{org.apache.logging.log4j.core.async.perftest}} package.)_
> Improve PatternLayout performance
> ---------------------------------
>
> Key: LOG4J2-930
> URL: https://issues.apache.org/jira/browse/LOG4J2-930
> Project: Log4j 2
> Issue Type: Improvement
> Components: Appenders, Layouts
> Affects Versions: 2.1
> Reporter: Remko Popma
> Attachments: Perf-sync-logging2014-12-25.xlsx,
> perf-sync-formatting.png
>
>
> While doing performance analysis for LOG4J2-928 (MemoryMappedFileAppender), I
> got some surprising results. From experience with a work project I knew the
> latency of writing to a memory mapped file was quite similar to using the
> Disruptor, but I was getting no more than 200,000 msg/sec, while on the same
> machine async loggers can achieve a throughput of several million msg/sec.
> I started experimenting with binary messages and various layout options and
> it turns out that formatting can make a huge difference. Without formatting,
> the memory mapped file appender reached 3.5 million msg/sec.
> I'd like to share the results here. _(Results are for tests with
> RandomAccessFile (RAF), which had more stable results. For some reason memory
> mapped file test results were very noisy. Need to do more work there.)_
> !perf-sync-formatting.png!
> ||Configuration||Avg. msg/sec||
> |async loggers (for reference - I/O and formatting done in background
> thread)|4,719,766|
> |sync RAF, noflush, no layout, fixed byte[] BinaryMsg (run 1)|3,977,222|
> |sync RAF, noflush, no layout, fixed byte[] BinaryMsg (run 2)|3,979,520|
> |sync RAF, noflush, no layout, fixed string.getBytes() BinaryMsg|3,213,756|
> |sync RAF, noflush, PatternLayout {{%m%n}} |1,900,037|
> |sync RAF, noflush, PatternLayout {{%m %ex%n}} |1,755,573|
> |sync RAF, noflush, PatternLayout {{%d\{UNIX_MILLIS} %m%n}} |1,650,131|
> |sync RAF, noflush, PatternLayout %d\{UNIX_MILLIS} {{%m %ex %n}} |1,331,707|
> |sync RAF, noflush, PatternLayout {{%d %m %ex%n}} |1,194,184|
> |sync RAF, noflush, PatternLayout {{%d \[%t] %m %ex%n}} |1,027,927|
> |sync RAF, noflush, PatternLayout {{%d %p \[%t] %m %ex%n}} |939,122|
> |sync RAF, noflush, PatternLayout {{%d %p %c\{1.} \[%t] %m %ex%n}} |595,663|
> |sync RAF, noflush, PatternLayout {{%d %p %c\{1.} \[%t] %X\{aKey} %m %ex%n}}
> |573,651|
> |sync File (buffered), noflush, fixed byte\[] BinaryMsg, PatternLayout {{%d
> %p %c\{1.} \[%t] %X\{aKey} %m %ex%n}} |551,919|
> |sync RAF, flush, no layout, fixed byte\[] BinaryMsg |432,558|
> |sync File (non-buffered), noflush, fixed byte\[] BinaryMsg, PatternLayout
> {{%d %p %c\{1.} \[%t] %X\{aKey} %m %ex%n}} |244,701|
> |sync File (non-buffered), flush, fixed byte\[] BinaryMsg, PatternLayout {{%d
> %p %c\{1.} \[%t] %X\{aKey} %m %ex%n}} |238,975|
> |sync File (buffered), flush, fixed byte\[] BinaryMsg, PatternLayout {{%d %p
> %c\{1.} \[%t] %X\{aKey} %m %ex%n}} |232,540|
> |sync RAF, flush, PatternLayout {{%d %p %c\{1.} \[%t] %X\{aKey} %m %ex%n}}
> |205,833|
> Some things to note:
> * First note the big difference in performance (3.2 M to 1.9 M msg/s) when
> going from no layout to PatternLayout "%m%n".
> * Second, every added PatternLayout option makes throughput noticeably worse.
> * Buffered, non-flushing appenders are fast because they avoid disk I/O, but
> innocuous-looking formatting options can undo most of the gains.
> The formatting options with the most impact seem to be:
> * {{%d}} ( {{%m %ex%n}}: 1,755,573 vs {{%d %m %ex%n}} 1,194,184)
> * {{%t}} ({{%d %m %ex%n}} 1,194,184 vs {{%d \[%t] %m %ex%n}} 1,027,927)
> * {{%c}} ({{%d %p \[%t] %m %ex%n}} 939,122 vs {{%d %p %c\{1.} \[%t] %m
> %ex%n}} 595,663)
> Some of these are surprising. I expected time formatting to have some impact,
> but the logger ({{%c}})? (It could be the precision specifier that makes it
> slow, need to do more analysis here...)
> It should be possible to improve this a lot. One idea is to cache constant
> strings like the logger names and thread names. Another idea is to avoid
> copying data multiple times into various StringBuilders, and instead have a
> custom Buffer that produces a byte array result directly.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
