Performance

One of the often-cited arguments against logging is its computational cost. This is a legitimate concern as even moderately sized applications can generate thousands of log requests. Much effort was spent measuring and tweaking logging performance. Log4j claims to be fast and flexible: speed first, flexibility second.

The user should be aware of the following performance issues.

  1. Logging performance when logging is turned off.

    When logging is turned off entirely or just for a set of Levels, the cost of a log request consists of two method invocations plus an integer comparison. On a 2.53 GHz Intel Core 2 Duo MacBook Pro calling isDebugEnabled 10 million times produces an average result in nanoseconds of:

                Log4j: 4
                Logback: 5
                Log4j 2: 3
                
    The numbers above will vary slightly from run to run so the only conclusion that should be drawn is that all 3 frameworks perform similarly on this task.

    However, The method invocation involves the "hidden" cost of parameter construction.

    For example,

                  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
                
    incurs the cost of constructing the message parameter, i.e. converting both integer i and entry[i] to a String, and concatenating intermediate strings, regardless of whether the message will be logged or not. This cost of parameter construction can be quite high and it depends on the size of the parameters involved. A comparison run on the same hardware as above yields:
                Log4j: 188
                Logback: 183
                Log4j 2: 188
                
    Again, no conclusion should be drawn regarding relative differences between the frameworks on this task, but it should be obvious that it is considerably more expensive than simply testing the level.

    The best approach to avoid the cost of parameter construction is to use Log4j 2's formatting capabilities. For example, instead of the above write:

                logger.debug("Entry number: {} is {}", i, entry[i]);
                
    Using this approach, a comparison run again on the same hardware produces:
                Log4j: Not supported
                Logback: 9
                Log4j 2: 4
                
    These results show that the difference in performance between the call to isDebugEnabled and logger.debug is barely discernable.

    In some circumstances one of the parameters to logger.debug will be a costly method call that should be avoided if debugging is disabled. In those cases write:

                if(logger.isDebugEnabled() {
                    logger.debug("Entry number: " + i + " is " + entry[i].toString());
                }
                

    This will not incur the cost of whatever the toString() method needs to do if debugging is disabled. On the other hand, if the logger is enabled for the debug level, it will incur twice the cost of evaluating whether the logger is enabled or not: once in isDebugEnabled and once in debug. This is an insignificant overhead because evaluating a logger takes about 1% of the time it takes to actually log.

    Certain users resort to preprocessing or compile-time techniques to compile out all log statements. This leads to perfect performance efficiency with respect to logging. However, since the resulting application binary does not contain any log statements, logging cannot be turned on for that binary. This seems to be a disproportionate price to pay in exchange for a small performance gain.

  2. The performance of deciding whether to log or not to log when logging is turned on.

    Unlike Log4j and Logback, Log4j 2 Loggers don't "walk a hierarchy". Loggers point directly to the Logger configuration that best matches the Logger's name. This incurs extra overhead when the Logger is first created but reduces the overhead every time the Logger is used.

  3. Actually outputting log messages

    This is the cost of formatting the log output and sending it to its target destination. Here again, a serious effort was made to make layouts (formatters) perform as quickly as possible. The same is true for appenders. One of the fundamental tenants of Log4j 2 is to use immutable objects whenever possible and to lock at the lowest granularity possible. However, the cost of actually formatting and delivering log events will never be insignificant. For example, the results of writing to a simple log file using the same format using Log4j, Logback and Log4j 2 are:

                Log4j: 4220
                Logback: 9671
                Log4j 2: 4615
                

    These results show that actually writing out the events can be at least 1000 times more expensive than when they are disabled.

  4. Advanced Filtering

    Both Logback and Log4j 2 support advanced filtering. Logback calls them TurboFilters while Log4j 2 has a single Filter object. Advanced filtering provides the capability to filter LogEvents using more than just the Level before the events are passed to Appenders. However, this flexibility does come with some cost. Since multi-threading can also have an impact on the performance of advanced filtering, the table below shows the difference in performance in two different sets of context-wide filters running on the same hardware as the previous tests using various numbers of threads.

    Test 1 thread 2 threads 5 threads 10 threads 20 threads 50 threads
    Logback MDCFilter 37 50 145 316 606 1670
    Log4j 2 ThreadContextMapFilter 30 35 85 165 341 864
    Logback MarkerFilter 17 24 59 115 234 547
    Log4j 2 MarkerFilter 4 5 7 20 35 92

The performance results above were all derived from running the DebugDisabledPerformanceComparison, FilterPerformanceComparison, and PerformanceComparison junit tests which can be found in the Log4j 2 unit test source directory.