Description
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.)
| 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.
Attachments
Attachments
Issue Links
- depends upon
-
LOG4J2-812 Performance optimization: avoid use of synchronized SimpleDateFormat in DatePatternConverter
-
- Resolved
-
-
LOG4J2-935 Performance: which String.getBytes method to use
-
- Resolved
-
-
-
- Resolved
-
-
-
- Resolved
-
- is depended upon by
-
LOG4J2-928 Lock-free synchronous sub-microsecond appender
-
- Open
-
- is superceded by
-
-
- Open
-