Java Language Logging (java.util.logging) Logging complex messages (efficiently)
Example
Let's look at a sample of logging which you can see in many programs:
public class LoggingComplex {
private static final Logger logger =
Logger.getLogger(LoggingComplex.class.getName());
private int total = 50, orders = 20;
private String username = "Bob";
public void takeOrder() {
// (...) making some stuff
logger.fine(String.format("User %s ordered %d things (%d in total)",
username, orders, total));
// (...) some other stuff
}
// some other methods and calculations
}
The above example looks perfectly fine, but many programmers forgets that Java VM is stack machine. This means that all method's parameters are calculated before executing the method.
This fact is crucial for logging in Java, especially for logging something in low levels like FINE, FINER, FINEST which are disabled by default. Let's look at Java bytecode for the takeOrder() method.
The result for javap -c LoggingComplex.class is something like this:
public void takeOrder();
Code:
0: getstatic #27 // Field logger:Ljava/util/logging/Logger;
3: ldc #45 // String User %s ordered %d things (%d in total)
5: iconst_3
6: anewarray #3 // class java/lang/Object
9: dup
10: iconst_0
11: aload_0
12: getfield #40 // Field username:Ljava/lang/String;
15: aastore
16: dup
17: iconst_1
18: aload_0
19: getfield #36 // Field orders:I
22: invokestatic #47 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
25: aastore
26: dup
27: iconst_2
28: aload_0
29: getfield #34 // Field total:I
32: invokestatic #47 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
35: aastore
36: invokestatic #53 // Method java/lang/String.format:(Ljava/lang/String;[Ljava/lang/Object;)Ljava/lang/String;
39: invokevirtual #59 // Method java/util/logging/Logger.fine:(Ljava/lang/String;)V
42: return
Line 39 runs the actual logging. All of the previous work (loading variables, creating new objects, concatenating Strings in format method) can be for nothing if logging level is set higher then FINE (and by default it is). Such logging can be very inefficient, consuming unnecessary memory and processor resources.
That's why you should ask if the level you want to use is enabled.
The right way should be:
public void takeOrder() {
// making some stuff
if (logger.isLoggable(Level.FINE)) {
// no action taken when there's no need for it
logger.fine(String.format("User %s ordered %d things (%d in total)",
username, orders, total));
}
// some other stuff
}
Since Java 8:
The Logger class has additional methods that take a Supplier<String> as parameter, which can simply be provided by a lambda:
public void takeOrder() {
// making some stuff
logger.fine(() -> String.format("User %s ordered %d things (%d in total)",
username, orders, total));
// some other stuff
}
The Suppliers get()method - in this case the lambda - is only called when the corresponding level is enabled and so the ifconstruction is not needed anymore.
