[
https://issues.apache.org/jira/browse/LOG4J2-930?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma updated LOG4J2-930:
-------------------------------
Attachment: LOG4J2-930-CachedStringBuffer.txt
Attached sample patch LOG4J2-930-CachedStringBuffer.txt
> 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: LOG4J2-930-CachedStringBuffer.txt,
> 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: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
