[jira] [Commented] (LOG4J2-930) Improve PatternLayout performance

["Remko Popma (JIRA)" <ji...@apache.org>]

    [ 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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org