Campaign to Eliminate Log4J Pattern Layouts containing %L in Performance Sensitive Components.

A fantastically horrible title, but please savor this trivial homespun tale of squeezing the microseconds out of my underwear  Log4J configuration.  

At my new place of employ, I was unaccustomed to seeing the following highlighted visage in log statements: 

2012-02-06 14:00:46,916 INFO  [Thread-2] ContextLoader (189) - Root WebApplicationContext: initialization started

I nary gave it further thought until one day I tripped over a typical LOG4J patterns in use around these parts: 

  <param name="ConversionPattern" value="%d %-5p [%t] %c{1} (%L) - %m%n" />

It turns out that conversion pattern reckons the source file line number.  I'm assuming it is employed to aid developers.  However, the use of that little critter comes with the following caution in the Log4j JavaDocs: 

Used to output the line number from where the logging request was issued. WARNING Generating caller location information is extremely slow and should be avoided unless execution speed is not an issue.

So .. it's been nagging me.  Just how slow could it be?   Well ... I finally did a what they call a micro-benchmark using Google's Caliper framework.  I tell you what!  That Caliper is a marvel – it intercepts stdout & stderr, warms up caches, heats up the JIT compiler, and all them other gory details to help make sense out of measuring things in a JVM.  

I ran a test using 2 patterns differing only by that %L bugger:

    private static final PatternLayout LINENUMBERS = new PatternLayout("%d %-5p [%t] %c{1} (%L) - %m%n");

    private static final PatternLayout NO_LINENUMBERS = new PatternLayout("%d %-5p [%t] %c{1} - %m%n");

   

Ohmygosh! There was an order of magnitude difference: 

 0% Scenario{vm=java, trial=0, benchmark=LineNumbers} 816290.85 ns; σ=6878.06 ns @ 3 trials

50% Scenario{vm=java, trial=0, benchmark=NoLineNumbers} 76665.96 ns; σ=22184.19 ns @ 10 trials

             benchmark    us linear runtime

  LineNumbers_no_parms 816.3 ==============================

NoLineNumbers_no_parms  76.7 ==

vm: java

trial: 0

Note: benchmarks printed 183162000 characters to System.out and 0 characters to System.err. Use --debug to see this output.

If I'm seeing what I think I'm seeing, that %L critter appears to cost almost millisecond per log line.   Don't let that get yer real-time system in trouble, ya hear?