Logging performance in Java
This is a topic that has probably been done to death, but I had some questions around it and decided to answer them for myself for a change. I thought it would be a decent way to restart my blog, which has always been a curious mix of my professional and personal lives.
Right now, I'm being paid to work on the JXTA project by OneDrum, which is a very interesting position to be in (Paid? To work on open source software?). The coding conventions for JXTA state that if you are going to write to a log, you must have code that looks like this:
Lets break it down, so we're clear on what exactly is happening here. First of all, Logging is a class with a bunch of static finals like SHOW_WARNING, SHOW_INFO, SHOW_FINEST that are initialised based on the value of a java system property. This is done in a static block. So, as soon as you touch the Logging class these are set up and never change again for the lifetime of that class (probably the lifetime of the process). These constants are provided within JXTA as a global, convenient way of changing the logging level of all JXTA code. It can also be done by changing the logging level for "net.jxta" in your logging configuration file.
Secondly, we have the call to LOG.isLoggable, which is typically a static final instance of java.util.logging.Logger for the class which we are currently within. This allows for logging level for specific classes, or package subtrees, to be respected by this code.
Finally, we have the call to LOG.warning() itself. Now, for those unfamiliar with logging, if you call warning() and warning level logs have been disabled, it will do nothing.
So, why do we do all of this? This leads to a number of questions.
How expensive is string concatenation, really?
What is the overhead of a method call?
What is the overhead of an if statement?
What is the cost of checking a static final field?
In order to answer all these questions, I wrote a little test to see the time difference if I
Called the log method directly, string concatenation before call
Called the log method directly, which used String.format() internally, with varargs accepted for parameters
Called a log method directly, which uses String.format() internally, method declared with fixed number of args
Checked only isLoggable() in the condition before logging
Checked both the constant and the condition before logging
Testing with a 2GHz Core 2 Duo Macbook using Java 1.5.0_19_b02-304, the results were:
Direct call, string concatenation: 28739ns (nanoseconds)
Direct call, String.format(), varargs: 57ns
Direct call, String.format(), fixed args: 34ns
Checking LOG.isLoggable first: 3.46ns
Checking constant, then LOG.isLoggable(): 3.18ns
So, allowing the string concatenation to occur is clearly something we want to avoid, given it is 3 orders of magnitude worse than the next-worst result. If you avoid constructing the string by using String.format() inside the log method (as slf4j allows), then the call time is measured in nanoseconds rather than microseconds.
However, a varargs method does not come for free. Presumably those arguments are packaged into a new array, which incurs an object instantiation cost. This is confirmed by doing the same call, but with a version of the log method that takes a fixed number of arguments, shaving 40% off the overall time per call.
But, the big savings occur if you don't even make that method call. If we call a simple accessor method like isLoggable(), things are an order of magnitude faster again.
Finally, if we check a static constant, it is marginally faster again. But now we're talking picoseconds faster, so it's negligible and going to be completely swamped by other factors.
What happens if we run this again, using Java 1.6.0_13-b03-211?
Direct call, string concatenation: 9795ns
Direct call, String.format(), varargs: 39ns
Direct call, String.format(), fixed args: 19ns
Checking LOG.isLoggable(): 0.005ns
Checking constant, then LOG.isLoggable(): 0.003ns
Well, string concatenation is an order of magnitude faster, but still not something we'd like to do lightly. Varargs and fixed method calls are both 40% faster again. But the nice surprise is that if we do the constant check, it's taking picoseconds. In other words, the VM is optimising the code to death, likely removing it.
Now, micro-benchmarks like this are notoriously inaccurate but what I think can be relied upon here are the orders of magnitudes involved. Checking a constant is stupidly fast, passing varargs to defer construction of the string is also good, but we should definitely still avoid direct string concatenation.
Is checking the constant still worthwhile, when calling a varargs style logging method is so fast? I guess this is where the debate lies these days. If you have run-time configurable logging in your code, you probably aren't worrying about losing a handful of nanoseconds to a method call. It's such a small amount you won't notice. It then comes down to whether you can tolerate having that if statement - does it compromise the readability of your code, to the extent that you're losing money for those extra few minutes it takes for someone to understand your method? Or even the time it takes to type that extra line of code?
Time is money, and a developer like me costs $0.01 per second. If your application isn't real-time (and if it were, it wouldn't be using logging), the cost per CPU second is a ridiculous fraction of that.
In conclusion for me, I can tolerate the if statements for now, as the cost of going back and "fixing" all the existing calls is ridiculously higher than the cost of leaving them in, and following the pattern. Ah, software development, it truly is the craft of the lazy pragmatist :)
Right now, I'm being paid to work on the JXTA project by OneDrum, which is a very interesting position to be in (Paid? To work on open source software?). The coding conventions for JXTA state that if you are going to write to a log, you must have code that looks like this:
if (Logging.SHOW_WARNING && LOG.isLoggable(Level.WARNING)) {
LOG.warning( "This is your final warning." );
}When I first saw this, I wanted to throw up. It's a lot of code for a relatively simple thing - I just want to write something to a log, if that log level is turned on. When you have a lot of logging in your code (and for a distributed system like JXTA that is virtually impossible to debug you need it), it's a major distraction from the intent of the surrounding code.Lets break it down, so we're clear on what exactly is happening here. First of all, Logging is a class with a bunch of static finals like SHOW_WARNING, SHOW_INFO, SHOW_FINEST that are initialised based on the value of a java system property. This is done in a static block. So, as soon as you touch the Logging class these are set up and never change again for the lifetime of that class (probably the lifetime of the process). These constants are provided within JXTA as a global, convenient way of changing the logging level of all JXTA code. It can also be done by changing the logging level for "net.jxta" in your logging configuration file.
Secondly, we have the call to LOG.isLoggable, which is typically a static final instance of java.util.logging.Logger for the class which we are currently within. This allows for logging level for specific classes, or package subtrees, to be respected by this code.
Finally, we have the call to LOG.warning() itself. Now, for those unfamiliar with logging, if you call warning() and warning level logs have been disabled, it will do nothing.
So, why do we do all of this? This leads to a number of questions.
How expensive is string concatenation, really?
What is the overhead of a method call?
What is the overhead of an if statement?
What is the cost of checking a static final field?
In order to answer all these questions, I wrote a little test to see the time difference if I
Called the log method directly, string concatenation before call
Called the log method directly, which used String.format() internally, with varargs accepted for parameters
Called a log method directly, which uses String.format() internally, method declared with fixed number of args
Checked only isLoggable() in the condition before logging
Checked both the constant and the condition before logging
Testing with a 2GHz Core 2 Duo Macbook using Java 1.5.0_19_b02-304, the results were:
Direct call, string concatenation: 28739ns (nanoseconds)
Direct call, String.format(), varargs: 57ns
Direct call, String.format(), fixed args: 34ns
Checking LOG.isLoggable first: 3.46ns
Checking constant, then LOG.isLoggable(): 3.18ns
So, allowing the string concatenation to occur is clearly something we want to avoid, given it is 3 orders of magnitude worse than the next-worst result. If you avoid constructing the string by using String.format() inside the log method (as slf4j allows), then the call time is measured in nanoseconds rather than microseconds.
However, a varargs method does not come for free. Presumably those arguments are packaged into a new array, which incurs an object instantiation cost. This is confirmed by doing the same call, but with a version of the log method that takes a fixed number of arguments, shaving 40% off the overall time per call.
But, the big savings occur if you don't even make that method call. If we call a simple accessor method like isLoggable(), things are an order of magnitude faster again.
Finally, if we check a static constant, it is marginally faster again. But now we're talking picoseconds faster, so it's negligible and going to be completely swamped by other factors.
What happens if we run this again, using Java 1.6.0_13-b03-211?
Direct call, string concatenation: 9795ns
Direct call, String.format(), varargs: 39ns
Direct call, String.format(), fixed args: 19ns
Checking LOG.isLoggable(): 0.005ns
Checking constant, then LOG.isLoggable(): 0.003ns
Well, string concatenation is an order of magnitude faster, but still not something we'd like to do lightly. Varargs and fixed method calls are both 40% faster again. But the nice surprise is that if we do the constant check, it's taking picoseconds. In other words, the VM is optimising the code to death, likely removing it.
Now, micro-benchmarks like this are notoriously inaccurate but what I think can be relied upon here are the orders of magnitudes involved. Checking a constant is stupidly fast, passing varargs to defer construction of the string is also good, but we should definitely still avoid direct string concatenation.
Is checking the constant still worthwhile, when calling a varargs style logging method is so fast? I guess this is where the debate lies these days. If you have run-time configurable logging in your code, you probably aren't worrying about losing a handful of nanoseconds to a method call. It's such a small amount you won't notice. It then comes down to whether you can tolerate having that if statement - does it compromise the readability of your code, to the extent that you're losing money for those extra few minutes it takes for someone to understand your method? Or even the time it takes to type that extra line of code?
Time is money, and a developer like me costs $0.01 per second. If your application isn't real-time (and if it were, it wouldn't be using logging), the cost per CPU second is a ridiculous fraction of that.
In conclusion for me, I can tolerate the if statements for now, as the cost of going back and "fixing" all the existing calls is ridiculously higher than the cost of leaving them in, and following the pattern. Ah, software development, it truly is the craft of the lazy pragmatist :)






