[
https://issues.apache.org/jira/browse/LOG4J2-930?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14742617#comment-14742617
]
Remko Popma commented on LOG4J2-930:
------------------------------------
I just finished with the docs for programmatic config and it's 04:30 Monday
morning. Oops. It will have to be later.
Another reason is to wait that this introduces another ThreadLocal and I'm not
really clear on our policy for this. We do already have a couple of
ThreadLocals, so it should not be a huge problem, but I would like to
understand the trade-offs better.
> 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]
