More‎ > ‎

The Wrong Use of Logging can be a Performance Killer in Enterprise Java

This article describes the impact to performance of wrong logging. In enterprise software one very common performance killer is logging. Don't get me wrong, logging is absolutely necessary during development, test and in production.

Standard Version of Logging

Quite often a logger is just created and use it like in the following code:

1
LOGGER.info(MESSAGE_PREFIX + Math.random() + MESSAGE_SUFIX);

In principle this is correct. But what really happens is that the message is created before the logging class decides, if the message should be printed to the configured output. 

Optimized Version of Logging

It is a good practice to check the logging level before the message string is created like in this:

1
2
3
if (LOGGER.isInfoEnabled()) { 
    LOGGER.info(MESSAGE_PREFIX + Math.random() + MESSAGE_SUFIX); 
}    

Results of a Micro Benchmark

The difference of the two version is significant


In the following table you find the raw data:

 Level  Standard  Optimized          Optimized/Standard
 INFO  9,477s   9,626s    
101,6%   
 ERROR  1,917s    0,167s  
8,7%  

The optimized version has a small overhead when a lot of logging happens, but is more than a factor 10 faster than the standard way. This is a good reason to use always the optimized logging version.

Source Code of Micro Benchmark

To reproduce the results just use the following class with log4j-1.2.13.jar and run with the VM Option
"-Xint". This means no JIT compilations.

File LoggerMicroBenchmark.java

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
package com.sw_engineering_candies.sample;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class LoggerMicroBenchmark {
    /** standard logger (see log4j.properties file for details) */
    private static final Logger LOGGER = Logger.getLogger(LoggerMicroBenchmark.class);
    /** some constants */
    private static final double FACTOR = 1000.0 * 1000.0 * 1000.0;
    private static final String MESSAGE_PREFIX = "This is a not to small message [";
    private static final String MESSAGE_SUFIX = "] which exlains what has happend ";

    private static long callLogger() {
        final long t = System.nanoTime();
        LOGGER.info(MESSAGE_PREFIX + Math.random() + MESSAGE_SUFIX);
        return System.nanoTime() - t;
    }
    private static long callLoggerOptimized() {
        final long t = System.nanoTime();
        if (LOGGER.isInfoEnabled()) {
            LOGGER.info(MESSAGE_PREFIX + Math.random() + MESSAGE_SUFIX);
        }
        return System.nanoTime() - t;
    }
    private static void runLogger() {
        long timeStandard = 0;
        long timeOptimized = 0;
        // change the order of execution in a random way
        for (int i = 1; i < 100000; i++) {
            if (Math.random() < 0.5) {
                timeStandard += callLogger();
                timeOptimized += callLoggerOptimized();
            } else {
                timeOptimized += callLoggerOptimized();
                timeStandard += callLogger();
            }
        }
        System.out.println("Level=" + LOGGER.getEffectiveLevel().toString());
        final double firstRunStandard = timeStandard / FACTOR;
        System.out.print(String.format("Standard= %.3f", firstRunStandard) + "s\t");
        final double secondRunOptimized = timeOptimized / FACTOR;
        System.out.print(String.format("Optimized=%.3f", secondRunOptimized) + "s\t");
        final double ratio = secondRunOptimized / firstRunStandard;
        System.out.print(String.format("Optimized/Standard=%.1f", ratio*100) + "%\n\n");
    }
    public static void main(final String[] args) {
        LOGGER.setLevel(Level.INFO);
        runLogger();
        LOGGER.setLevel(Level.ERROR);
        runLogger();
    }
}

File log4j.properties

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
# Set root category priority to DEBUG and set its only appender to A1
# ALL|DEBUG|INFO|WARN|ERROR|FATAL|OFF
log4j.rootCategory=DEBUG, A2
# A2 is rolling file appender:
log4j.appender.A2.file=logger.txt
log4j.appender.A2=org.apache.log4j.RollingFileAppender
log4j.appender.A2.append=false
log4j.appender.A2.MaxBackupIndex=100
log4j.appender.A2.MaxFileSize=15MB
log4j.appender.A2.layout=org.apache.log4j.PatternLayout
log4j.appender.A2.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%

Sponsored Link