Remko Popma created LOG4J2-930:
----------------------------------
Summary: 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
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.
!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]
