Log4j calls are slow in getStackTrace calls

Environment

• Log4j
• JBoss Enterprise Application Platform (EAP)

Issue

• Our application is facing slowness in logging calls and thread dumps show log4j lock contention with lock owners frequently in getStackTrace calls like below:

"default task-857" #2137 prio=5 os_prio=0 tid=0x0000000019b91000 nid=0x3c51b2 runnable [0x00007fe092996000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.Throwable.getStackTraceElement(Native Method)
	at java.lang.Throwable.getOurStackTrace(Throwable.java:827)
	- locked <0x00000007883ec1b0> (a java.lang.Throwable)
	at java.lang.Throwable.getStackTrace(Throwable.java:816)
	at org.jboss.logmanager.JDKSpecific.calculateCaller(JDKSpecific.java:86)
	at org.jboss.logmanager.ExtLogRecord.calculateCaller(ExtLogRecord.java:335)
	at org.jboss.logmanager.ExtLogRecord.getSourceFileName(ExtLogRecord.java:383)
	at org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:175)
	at org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:464)
	at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
	at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
	at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	- locked <0x0000000713b2e058> (a org.apache.log4j.DailyRollingFileAppender)
	at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:34)
	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:77)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:333)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.Logger.logRaw(Logger.java:852)
	at org.jboss.logmanager.Logger.log(Logger.java:598)
	at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71)

"default task-18810" #566701 prio=5 os_prio=0 tid=0x0000557ab9d09800 nid=0x5f9d runnable [0x00007f747e449000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.Throwable.getStackTraceElement(Native Method)
	at java.lang.Throwable.getOurStackTrace(Throwable.java:828)
	- locked <0x00007f76b8167a08> (a java.lang.Exception)
	at java.lang.Throwable.getStackTrace(Throwable.java:817)
	at java.lang.Thread.getStackTrace(Thread.java:1559)
	at org.apache.logging.log4j.core.impl.Log4jLogEvent.calcLocation(Log4jLogEvent.java:386)
	at org.apache.logging.log4j.core.impl.Log4jLogEvent.getSource(Log4jLogEvent.java:378)
	at org.apache.logging.log4j.core.pattern.FileLocationPatternConverter.format(FileLocationPatternConverter.java:57)
	at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
	at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:197)
	at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:55)
	at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:67)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:727)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:716)
	at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:232)

Resolution

• Review application log4j configurations and remove %F, %C, %l, %L, and %M options from any log patterns

Root Cause

• These calls would suggest log patterns are used with the %F, %C, %l, %L, or %M option. Per the 'Location Information' section of Content from logging.apache.org is not included.log4j docs, that will be expensive logging so would not be recommended for performance:

If one of the layouts is configured with a location-related attribute like HTML locationInfo, or one of the patterns %C or %class, %F or %file, %l or %location, %L or %line, %M or %method, Log4j will take a snapshot of the stack, and walk the stack trace to find the location information.

This is an expensive operation: 1.3 - 5 times slower for synchronous loggers.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.