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

Performance regression in RewriteAppender

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.6
    • Fix Version/s: 2.6
    • Component/s: Appenders
    • Labels:
      None

      Description

      While working on LOG4J2-1179, I ran into these benchmark results:

      Benchmark                                                         Mode  Samples           Score            Error  Units
      o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderRewrite    thrpt        5    44263670.008 ±   17389305.070  ops/s
      o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endRewrite     thrpt        5       37254.554 ±      16440.919  ops/s
      

      In plain English: directly calling RewriteAppender.append(LogEvent) can do 44 million ops/sec, but when calling rewriteLogger.debug(msg) to invoke a logger that calls this appender, all of a sudden throughput drops to 37 thousand ops/sec. That's 1000x slower. Fishy...

      Turns out that when rewriting the event we are now including caller location information (taking a snapshot of the stack and walking it). Ouch.

      This is a regression caused by the garbage-free stuff. Rewriting the event makes a copy of the event and avoids calling LogEvent.getSource() only if the event is an instance of Log4jLogEvent, but now we are passing in MutableLogEvent.

      The fix is to update Log4jLogEvent.Builder to also avoid calling getSource when copying from a MutableLogEvent.

        Attachments

          Activity

            People

            • Assignee:
              remkop@yahoo.com Remko Popma
              Reporter:
              remkop@yahoo.com Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: