Support Article

Thread blocked on log4j Category.callAppenders()

SA-24725

Summary



The users' two production JVMs out of 12 JVMs were hung and had to be recycled.

Error Messages


Java core blocked thread

3XMTHREADINFO      "WebContainer : 38" J9VMThread:0x000000003404CC00, j9thread_t:0x000001005B85CE70, java/lang/Thread:0x000000070A551208, state:B, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x3B6DA, isDaemon:true)
3XMTHREADINFO1            (native thread ID:0x458035B, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/pega/apache/log4j/Category.callAppenders(Category.java:204(Compiled Code))
4XESTACKTRACE                at com/pega/apache/log4j/Category.forcedLog(Category.java:391)
4XESTACKTRACE                at com/pega/apache/log4j/Category.alert(Category.java:728)
4XESTACKTRACE                at com/pega/pegarules/priv/LogHelper.doAlert(LogHelper.java:1183(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/priv/LogHelper.alert(LogHelper.java:906(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/priv/LogHelper.alert(LogHelper.java:892)
4XESTACKTRACE                at com/pega/pegarules/data/internal/access/ConnectionManagerImpl.getConnection(ConnectionManagerImpl.java:1351(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/data/internal/access/ConnectionManagerImpl.getConnection(ConnectionManagerImpl.java:947(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/data/internal/access/ThreadConnectionStoreImpl.getConnection(ThreadConnectionStoreImpl.java:392(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/data/internal/access/LockManagerImpl.unlockForRequestor(LockManagerImpl.java:2015(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/engineinterface/etier/impl/LockManagerImpl._unlockForRequestor_privact(LockManagerImpl.java:166(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/engineinterface/etier/impl/LockManagerImpl.unlockForRequestor(LockManagerImpl.java:145(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/engineinterface/etier/ejb/LockManagerBean.unlockForRequestor(LockManagerBean.java:186(Compiled Code))
4XESTACKTRACE                at sun/reflect/GeneratedMethodAccessor129.invoke(Bytecode PC:40(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:611(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/internal/bootstrap/PRBootstrap.invokeMethod(PRBootstrap.java:348(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/internal/bootstrap/PRBootstrap.invokeMethodPropagatingThrowable(PRBootstrap.java:389(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/internal/bootstrap/PRBootstrap.invokeMethod(PRBootstrap.java:438(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/internal/etier/ejb/LockManagerBeanBoot.unlockForRequestor(LockManagerBeanBoot.java:168(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/internal/etier/interfaces/EJSLocalStatelessLockManager_9a306bdc.unlockForRequestor(Bytecode PC:50(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/data/internal/access/LockManagerImpl.unlockForRequestor(LockManagerImpl.java:1978(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/mgmt/base/RequestorPassivation.cleanupImpl(RequestorPassivation.java:555(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/mgmt/PRRequestorBase.cleanup(PRRequestorBase.java:807(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/mgmt/PRRequestorImpl.cleanup(PRRequestorImpl.java:305(Compiled Code))
4XESTACKTRACE                at com/pega/pegarules/session/internal/mgmt/base/NodeRequestorMgt.cleanupInner(NodeRequestorMgt.java:912)
4XESTACKTRACE                at sun/reflect/GeneratedMethodAccessor127.invoke(Bytecode PC:56(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))


Steps to Reproduce



Not Applicable 

Root Cause



A defect or configuration issue in the operating environment. 
The JVMs were monitored nodes of an AES server. Since the AES server was under load with requests queued– monitored nodes’ SOAP messages have been held-back at the monitored nodes causing the log4j appender calls blocking / waiting for the response from the AES server.


Resolution



Make the following change to the operating environment:

The “Blocking” param for the AsyncAppenders have not been set to “false”. By default the value is “true” when not specified or the AsyncAppender will wait if there is no space available in the event buffer. 

Modify the following APPENDERs under prlogging.xml for the monitored nodes – 

<appender name="ASYNC" class="com.pega.apache.log4j.AsyncAppender">
<param name="BufferSize" value="1280"/>
<param name="Blocking" value="false"/>
[…]
</appender>

<appender name="ALERT-ASYNC" class="com.pega.apache.log4j.AsyncAppender">
<param name="BufferSize" value="1280"/>
<param name="Blocking" value="false"/>
[…]
</appender>

The above change should protect the monitored nodes should the AES server backup threads. The DEFAULT_BUFFER_SIZE of 128 events has been increased by a factor of 10.
 

Published June 20, 2016 - Updated July 31, 2016

Have a question? Get answers now.

Visit the Collaboration Center to ask questions, engage in discussions, share ideas, and help others.