Why some Log4j options are more expensive than others
Zarar Siddiqi has an article on why some Log4j pattern options are more expensive than others and tend to slow a system down. A pattern option is the character ofter the ‘%’ sign in the following line:
log4j.appender.stdout.layout.ConversionPattern=
%d{ABSOLUTE} %5p [%c{1}] %m%n
Some options like %l or %L output the line number or the method name in your log file. These can be really nice to have when you are debugging code, but they come with a price.
However, according to the article, you should be very careful using these options. The reason is that:
What Log4J ends up doing is that for each debug(..) call, it creates an instance of Throwable which takes a snapshot of the runtime stack. It then proceeds to parse the stack to yield the current line of code being executed along with class and method information.
…constructing stack traces is a fairly expensive operation. When an Exception is created, the JVM needs to literally pause the processing and so it can get a good glimpse of the entire runtime stack - this includes classes, methods, line numbers etc - starting from Thread.run() all the way till the creation of Throwable.
However, in the logging scenario, the culprit is the call to the Throwable.fillInStackTrace() method in the Throwable constructor which gets invoked on each debug(..), info(..) and other logging calls. This is the only way to retrieve the logging information requested via the PatternLayout class.
I will definitely be more careful about what I put in the ConversionPattern from now on.
