Exactly how slow are C, F, L, l and M of PatternLa

Question

It's common knowledge that C, F, L, l and M of PatternLayout are slow:

WARNING Generating caller location information is extremely slow and should be avoided unless execution speed is not an issue.

Also, this book mentions that some applications can gain 10% speed only from changing the logging format.

But the question is, exactly how slow are these conversion characters?

Answer 1

Assuming you are not just academically interested in the answer, but are worried about the cost of logging in an actual application:

I've used them all in production applications and they have never posed a problem, primarily because logging is a relatively infrequent event. Of course, these applications were all I/O bound (not to disk/partition where the logging went) and the machines had plenty of CPU cycles to spare (but they were only PIII-1133 machines), but this holds for the vast majority of (web) applications. I'd just use them until profiling shows you logging is a bottleneck and not worry about it.

Answer 2

The primary reason that these are marked as slow, is because the information they represent is retrieved by throwing an exception and analyze the stack trace of the exception.

When PatternLayout was designed, stack trace generation was a very expensive process, so this was fair warning. Advances in JVM technology has improved on this so the process is not as expensive anymore. Even though there is faster methods to derive the needed information today, these are - to my knowledge - not being used due to attention to backwards compatibility with earlier versions of Java.

In other words, this is not as bad as it used to be.

Answer 3

I measured locally on my computer using a FileAppender. I warmed up the test nicely, measured many executions and averaged the (relatively consistent) results. The loop contained execs++;log.info("t");The exact numbers do not matter (because they depend on my computer) but proportions do. I used log4j-1.2.16.jar on Java 1.6.0_10 (Client VM).

It turns out that whenever any of the C, F, L, l or M appeared in the pattern, logging was at least 5 times slower.