JBoss becomes unresponsive with threads blocking on org.apache.log4j.spi.RootLogger
Environment
- JBoss Enterprise Application Platform (EAP)
Issue
-
JBoss becomes slow/unresponsive with many threads blocking on org.apache.log4j.spi.RootLogger like so:
"ajp-127.0.0.1-8009-1" daemon prio=10 tid=0x0000000062320800 nid=0x3b40 waiting for monitor entry [0x0000000045f89000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.log4j.Category.callAppenders(Category.java:201) - locked <0x0000000771a28f70> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.log(Category.java:853) at org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:257) -
Threads may also lock
org.apache.log4j.Logger, as seen below:
"ajp-127.0.0.1-8080-36" daemon prio=3 tid=0x0c320400 nid=0xed waiting for monitor entry [0x55349000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <0x8f07d578> (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.debug(Category.java:257)
Resolution
- Decrease logging verbosity.
- Fix any potential issues seen that can cause floods of frequent logging messages.
- Address any appender performance issues and avoid expensive ones like SMTP
- If the SMTPAppender is hanging on a socket write/connect with log4j locked, try the following flags to set timeouts for these operations:
-
mail.smtp.connectiontimeout=#milliseconds
-
mail.smtp.timeout=#milliseconds
-
Note these are not system properties but properties to apply to an smtp appender configuration or directly in any code creating the SMTP transport:
Properties properties = new Properties(); properties.setProperty("mail.smtp.host", HOST); properties.setProperty("mail.smtp.port", "" + port); properties.setProperty("mail.smtp.connectiontimeout", #ofMS); properties.setProperty("mail.smtp.timeout", #ofMS); Session session = Session.getInstance(properties); Transport t = session.getTransport("smtp"); try { // use transport }
-
"Dispatcher-Thread-1436" daemon prio=10 tid=0xae653c00 nid=0x1b59 runnable [0xae27d000..0xae27dff0]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
- locked <0xf0abfa50> (a java.net.SocksSocketImpl)
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
at java.net.Socket.connect(Socket.java:519)
at java.net.Socket.connect(Socket.java:469)
at com.sun.mail.util.SocketFetcher.createSocket(SocketFetcher.java:233)
at com.sun.mail.util.SocketFetcher.getSocket(SocketFetcher.java:189)
at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1359)
at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:412)
at javax.mail.Service.connect(Service.java:288)
- locked <0xf0ab1230> (a com.sun.mail.smtp.SMTPTransport)
at javax.mail.Service.connect(Service.java:169)
at javax.mail.Service.connect(Service.java:118)
at javax.mail.Transport.send0(Transport.java:188)
at javax.mail.Transport.send(Transport.java:118)
at org.apache.log4j.net.SMTPAppender.sendBuffer(Unknown Source)
at org.apache.log4j.net.SMTPAppender.append(Unknown Source)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
- locked <0xe1c58a90> (a org.apache.log4j.net.SMTPAppender)
- Switch to use the AsyncAppender so that threads do not have to handle logging directly but can instead send it to a back ground log4j thread to handle the logging.
EAP 6 jboss logging configuration for the async appender:
CLI: /subsystem=logging/async-handler=async-handler:add(queue-length=1024, overflow-action="discard", level="INFO", subhandlers=["FILE"])
<subsystem xmlns="urn:jboss:domain:logging:1.3">
<async-handler name="async-handler">
<level name="INFO"/>
<queue-length value="1024"/>
<overflow-action value="discard"/>
<subhandlers>
<handler name="FILE"/>
</subhandlers>
</async-handler>
<size-rotating-file-handler name="FILE" autoflush="true">
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
</formatter>
<level name="INFO"/>
<file relative-to="jboss.server.log.dir" path="server.log"/>
<rotate-size value="10m"/>
<max-backup-index value="5"/>
<append value="false"/>
</size-rotating-file-handler>
<logger category="com.arjuna">
<level name="WARN"/>
</logger>
<logger category="org.apache.tomcat.util.modeler">
<level name="WARN"/>
</logger>
<logger category="org.jboss.as.config">
<level name="DEBUG"/>
</logger>
<logger category="sun.rmi">
<level name="WARN"/>
</logger>
<logger category="jacorb">
<level name="WARN"/>
</logger>
<logger category="jacorb.config">
<level name="ERROR"/>
</logger>
<root-logger>
<level name="INFO"/>
<handlers>
<handler name="async-handler"/>
</handlers>
</root-logger>
</subsystem>
-
If already using the AsyncAppender and stalls are still experienced like this, then threads are likely blocking because the AsyncAppender's buffer is full. By default, threads will block when this is full until messages are successfully logged by the log4j dispatcher thread to free up more space in the buffer. If the dispatcher thread dies for any reason while threads are waiting on this buffer, then they will be stuck waiting indefinitely. To help prevent/avoid these issues, you can either increase the buffer size or disable blocking. Note that with blocking disabled, messaging events will be skipped over and not logged when this is experienced but threads will still progress. You can refer to What happens to logging events when the AsyncAppender buffer fills in non-blocking mode? for clarification on what happens in the event of a full queue with non-blocking mode:
<appender name="ASYNC" class="org.apache.log4j.AsyncAppender"> <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/> <param name="Threshold" value="INFO"/> <param name="Blocking" value="false"/> <param name="bufferSize" value="256"/> <appender-ref ref="FILE"/> </appender> -
Ensure the
log4j.debugandlog4j.configDebugsystem properties are not set to true. These enable debug messages from log4j that print to STDOUT; those can feed back through log4j to cause deadlocks even when using the AsyncAppender, for example:
"AsyncAppender-Dispatcher-Thread-101" #178 daemon prio=5 os_prio=0 tid=0x00000000249a8000 nid=0x306c waiting for monitor entry [0x0000000022f1e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock <0x000000070c742d28> (a org.apache.log4j.AsyncAppender)
at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:34)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:302)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:310)
at org.jboss.logmanager.Logger.logRaw(Logger.java:719)
at org.jboss.logmanager.Logger.log(Logger.java:504)
at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71)
- locked <0x0000000700678760> (a java.lang.StringBuilder)
at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
- locked <0x00000007006788d0> (a sun.nio.cs.SingleByte$Decoder)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x0000000700678700> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
- locked <0x00000007006668d0> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.newLine(PrintStream.java:546)
- locked <0x0000000700678700> (a java.io.PrintStream)
at java.io.PrintStream.println(PrintStream.java:807)
- locked <0x0000000700678700> (a java.io.PrintStream)
at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:474)
at org.apache.log4j.helpers.LogLog.debug(LogLog.java:100)
at org.apache.log4j.FileAppender.setFile(FileAppender.java:281)
- locked <0x000000070c743af8> (a org.apache.log4j.RollingFileAppender)
at org.apache.log4j.RollingFileAppender.setFile(RollingFileAppender.java:207)
- locked <0x000000070c743af8> (a org.apache.log4j.RollingFileAppender)
at org.apache.log4j.RollingFileAppender.rollOver(RollingFileAppender.java:191)
at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:280)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x000000070c743af8> (a org.apache.log4j.RollingFileAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.AsyncAppender$Dispatcher.run(AsyncAppender.java:586)
- If you see the AsyncAppender stall because the dispatcher thread has died, you could consider increasing your thread stack size (-Xss) and/or max heap (-Xmx) as StackOverflow or heap space OOME could be a common cause of its death. You may see the dispatcher thread still in the thread dumps, but stalled trying to log its fatal exception. In this case, capture a heap dump to try to get more information on the fatal exception:
"Dispatcher-Thread-7" daemon prio=10 tid=0x00007fa96063e800 nid=0x69bd waiting for monitor entry [0x00007fa97970f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <0x000000008ab24950> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:835)
at org.jboss.logging.util.LoggerStream.write(LoggerStream.java:156)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:85)
- locked <0x000000008daaacb0> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168)
at java.io.PrintStream.write(PrintStream.java:477)
- locked <0x000000008da840f8> (a org.jboss.logging.util.LoggerStream)
at java.io.PrintStream.print(PrintStream.java:619)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:983)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:976)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:976)
at java.lang.Thread.dispatchUncaughtException(Thread.java:1874)
Root Cause
- Heavy logging activity and/or slow appender performance causes threads to back up on log4j
- The AsyncAppender dispatcher thread is stalled and the buffer is full for long periods to stall threads in logging
- The AsyncAppender dispatcher thread died while threads were waiting on the buffer, effectively causing a deadlock
log4j.debugorlog4j.configDebugwere set to true to enable debug messages from log4j, allowing for a deadlock
Diagnostic Steps
- Troubleshoot using thread dumps and additional steps mentioned in Java application unresponsive
- Checking logs for an abundance of common, frequent messages that could lead to very heavy logging activity
Components
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.