Java logging performance pitfalls

by Mikhail Vorontsov

In this article we will discuss possible performance issues with Java loggers. We will not discuss any java.util.logging.Handler implementations, because they are actually based on I/O classes discussed in other articles. Here we will discuss how to use java.util.logging.Logger in order not to write a slow Java logging code.

Logging arguments handling

The most important thing about Logger performance could be found in its JavaDoc:

On each logging call the Logger initially performs a cheap check of the request level (e.g. SEVERE or FINE) against the effective log level of the logger. If the request level is lower than the log level, the logging call returns immediately.

This knowledge will allow you to get rid of many code snippets like this in your code:

1
2
3
4
if ( logger.isLoggable( Level.FINE ) )
{
    logger.log( Level.FINE, "Log message" );
}
if ( logger.isLoggable( Level.FINE ) )
{
    logger.log( Level.FINE, "Log message" );
}

You are simply repeating the same check which is going to be done in the logger itself! So, why do you make it?

The usual reason for such check is doing some costly calculations while preparing data for your log call despite the fact that you may not need to write that log message. Let’s trace the log message path in order to understand what is the right way to use loggers.

The first important method to look at is Logger.log(Level level, String msg, Object params[]) – a multi argument version of a standard logging call. You must understand that you shouldn’t do any method calls as arguments to log methods. Pass objects instead. This is enough in order to pass the first line of defence. All log call parameters will be packed into a LogRecord structure and passed to the Handler.

Handlers are not particularly interesting because they pass LogRecord to java.util.logging.Formatter class.

Formatter.formatMessage( LogRecord ) is so interesting that a part of it worth quoting in order to better understand it:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
// Do the formatting.
try {
    Object parameters[] = record.getParameters();
    if (parameters == null || parameters.length == 0) {
        // No parameters.  Just return format string.
        return format;
    }
    // Is is a java.text style format?
    // Ideally we could match with
    // Pattern.compile("\\{\\d").matcher(format).find())
    // However the cost is 14% higher, so we cheaply check for
    // 1 of the first 4 parameters
    if (format.indexOf("{0") >= 0 || format.indexOf("{1") >=0 ||
                format.indexOf("{2") >=0|| format.indexOf("{3") >=0) {
       return java.text.MessageFormat.format(format, parameters);
    }
    return format;
 
} catch (Exception ex) {
    // Formatting failed: use localized format string.
    return format;
}
// Do the formatting.
try {
    Object parameters[] = record.getParameters();
    if (parameters == null || parameters.length == 0) {
        // No parameters.  Just return format string.
        return format;
    }
    // Is is a java.text style format?
    // Ideally we could match with
    // Pattern.compile("\\{\\d").matcher(format).find())
    // However the cost is 14% higher, so we cheaply check for
    // 1 of the first 4 parameters
    if (format.indexOf("{0") >= 0 || format.indexOf("{1") >=0 ||
                format.indexOf("{2") >=0|| format.indexOf("{3") >=0) {
       return java.text.MessageFormat.format(format, parameters);
    }
    return format;

} catch (Exception ex) {
    // Formatting failed: use localized format string.
    return format;
}

A check in the middle is one of the greatest things I have ever seen in JDK: if arguments #0, 1, 2 or 3 were not used in the format string – it is not a format string at all. Try to run the following line:

1
2
Logger.getAnonymousLogger().log( Level.SEVERE, "Log line {4} {5} {6}", new Object[] { 0, 1, 2, 3, 4, 5, 6 });
    
Logger.getAnonymousLogger().log( Level.SEVERE, "Log line {4} {5} {6}", new Object[] { 0, 1, 2, 3, 4, 5, 6 });
    

You will get an original format string with curly braces:

SEVERE: Log line {4} {5} {6}
    

But we got away from the topic. Our arguments will be passed untouched to java.text.MessageFormat.format.

The following code is responsible for converting all arguments to strings in the that method (I have removed a few lines for clarity):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
if (obj == null) {
    arg = "null";
} else if (obj instanceof Number) {
    // format number if can
    subFormatter = NumberFormat.getInstance(locale);
} else if (obj instanceof Date) {
    // format a Date if can
    subFormatter = DateFormat.getDateTimeInstance(
             DateFormat.SHORT, DateFormat.SHORT, locale);//fix
} else if (obj instanceof String) {
    arg = (String) obj;
} else {
    arg = obj.toString();
    if (arg == null) arg = "null";
}
if (obj == null) {
    arg = "null";
} else if (obj instanceof Number) {
    // format number if can
    subFormatter = NumberFormat.getInstance(locale);
} else if (obj instanceof Date) {
    // format a Date if can
    subFormatter = DateFormat.getDateTimeInstance(
             DateFormat.SHORT, DateFormat.SHORT, locale);//fix
} else if (obj instanceof String) {
    arg = (String) obj;
} else {
    arg = obj.toString();
    if (arg == null) arg = "null";
}

The last else statement if the most important for us – it means that if you passed a custom Object to the logger, then its toString method will be finally called deep inside the library classes. This means that if we want to avoid expensive calculations while preparing data for a log message, we need either use Logger.isLoggable and do all data preparation inside or write an object which does all calculations in its toString method.

Do not mix format string concatenation with log arguments

If you are aware of poor MessageFormat.format performance, then you may think that it is a good idea to replace format string arguments with string concatenation. Unfortunately, it is not safe – if you will have any special characters in your concatenated strings, you may end up with a broken log message. For example, having a single quote in the middle of your format string will treat the remaining part of the string as a literal. The following code snippet will print “Text with a single starts here {a} {1}” (pay attention to the absence of a quote in the middle of the string).

1
2
System.out.println( MessageFormat.format( "Text with a single ' starts here {a} {1}", "zero", "one" ) );
    
System.out.println( MessageFormat.format( "Text with a single ' starts here {a} {1}", "zero", "one" ) );
    

A small update to format string will end up in the exception being thrown:

1
2
System.out.println( MessageFormat.format( "Text with a single quote starts here {{0} {1}", "zero", "one" ) );
    
System.out.println( MessageFormat.format( "Text with a single quote starts here {{0} {1}", "zero", "one" ) );
    

It throws:

Exception in thread "main" java.lang.IllegalArgumentException: Unmatched braces in the pattern.
at java.text.MessageFormat.applyPattern(MessageFormat.java:508)
at java.text.MessageFormat.<init>(MessageFormat.java:363)
at java.text.MessageFormat.format(MessageFormat.java:835)
    

Luckily, if your log handler uses a standard Formatter, you won’t be exposed to exceptions vulnerability (go back to the Formatter example earlier in this article – it catches all exceptions thrown during formatting), but you may still log raw format strings in case of malicious input.

Summary

  • If you make expensive calculations while preparing data for log messages, either use Logger.isLoggable and do all data preparation inside or write an object which does all calculations in its toString method.
  • Never call Object.toString method in order to obtain a log message argument – just pass an original object. Logging framework will call toString method on your object.
  • Do not mix format string concatenation with log arguments – malicious concatenated string will allow your application user to break your logging/access data which was not supposed for user access.

Leave a Reply

Your email address will not be published. Required fields are marked *