Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-930

Improve PatternLayout performance

    XMLWordPrintableJSON

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Major
    • Resolution: Later
    • Affects Version/s: 2.1
    • Fix Version/s: None
    • Component/s: Appenders, Layouts
    • Labels:
      None

      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

        1. perf-sync-formatting.png
          197 kB
          Remko Popma
        2. Perf-sync-logging2014-12-25.xlsx
          17 kB
          Remko Popma
        3. LOG4J2-930-CachedStringBuffer.txt
          2 kB
          Remko Popma

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                rpopma Remko Popma
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: