We are using wildfly-9.01 for java web application. For logging, we are using log4j-1.2.17.jar for During load conditions application was using more CPU and became unresponsive.
After inspecting threaddump we came to know there were many threads in BLOCKED state.
Below logging thread was blocking other threads(around 100 threads)
"EJB default - 863" #2445 prio=5 os_prio=0 tid=0x00007feee00ec800 nid=0xc10c5 waiting for monitor entry [0x00007fed29cc8000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:56)
- locked <0x00007ff027670520> (a java.lang.Object)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:314)
at org.jboss.logmanager.Logger.logRaw(Logger.java:850)
at org.apache.log4j.Category.callAppenders(Category.java:69)
at org.apache.log4j.Category.forcedLog(Category.java:121)
at org.apache.log4j.Category.debug(Category.java:82)
at com.mypp.dms.locking.dao.LockDAO.getObjectActivityLockByLockedObjectIds(LockDAO.java:259)
at com.mypp.collab.locking.bizlogic.AdoddleLockEJB.getObjectActivityLockByLockedObjectIds(AdoddleLockEJB.java:173)
at sun.reflect.GeneratedMethodAccessor335.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:437)
at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:87)
at org.jboss.weld.interceptor.proxy.WeldInvocationContext.interceptorChainCompleted(WeldInvocationContext.java:98)
at org.jboss.weld.interceptor.proxy.WeldInvocationContext.proceed(WeldInvocationContext.java:117)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:104)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:54)
at sun.reflect.GeneratedMethodAccessor334.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)
at org.jboss.weld.interceptor.proxy.WeldInvocationContext.invokeNext(WeldInvocationContext.java:83)
at org.jboss.weld.interceptor.proxy.WeldInvocationContext.proceed(WeldInvocationContext.java:115)
at org.jboss.weld.bean.InterceptorImpl.intercept(InterceptorImpl.java:106)
at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:77)
at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:68)
at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:80)
at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:93)
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:437)
at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73)
at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:83)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:275)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:327)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:79)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:53)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:634)
at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:331)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:202)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
Locked ownable synchronizers:
- <0x00007ff03c0f32c0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
stacktrace of other threads which blocked due to above thread
"EJB default - 1974" #3695 prio=5 os_prio=0 tid=0x00007fef8408d000 nid=0xc2451 waiting for monitor entry [0x00007fece2758000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:56)
- waiting to lock <0x00007ff027670520> (a java.lang.Object)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:314)
at org.jboss.logmanager.Logger.logRaw(Logger.java:850)
at org.apache.log4j.Category.callAppenders(Category.java:69)
at org.apache.log4j.Category.forcedLog(Category.java:121)
at org.apache.log4j.Category.debug(Category.java:82)
at com.mypp.dms.forms.create.persistence.dao.FormCreateDAO.insertFormMessage(FormCreateDAO.java:246)
"EJB default - 1926" #3644 prio=5 os_prio=0 tid=0x00007fedc01d5000 nid=0xc241b waiting for monitor entry [0x00007fece5486000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:56)
- waiting to lock <0x00007ff027670520> (a java.lang.Object)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:314)
at org.jboss.logmanager.Logger.logRaw(Logger.java:850)
at org.apache.log4j.Category.callAppenders(Category.java:69)
at org.apache.log4j.Category.forcedLog(Category.java:121)
at org.apache.log4j.Category.debug(Category.java:82)
at com.mypp.dms.distribute.bizlogic.DistributionFacadeEJB.getDistributionGroupsForProjects(DistributionFacadeEJB.java:2855)
"EJB default - 1874" #3579 prio=5 os_prio=0 tid=0x00007ffa34ba1800 nid=0xc23d3 waiting for monitor entry [0x00007fece8dbf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:56)
- waiting to lock <0x00007ff027670520> (a java.lang.Object)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:314)
at org.jboss.logmanager.Logger.logRaw(Logger.java:850)
at org.apache.log4j.Category.callAppenders(Category.java:69)
at org.apache.log4j.Category.forcedLog(Category.java:121)
at org.apache.log4j.Category.debug(Category.java:82)
at com.mypp.dms.forms.create.bizlogic.CreateMsgSessionEJB.getFormTypeFixedFields(CreateMsgSessionEJB.java:378)
I have referred to some of the posts that suggest upgrading log4. Other than this, are there any config/changes that need to be checked to avoid this issue?
Thanks for looking here :-)
For logging, we are using
log4j-1.2.17.jar.
You certainly compiled your application code against Log4j 1, but the library is not used at runtime. The WildFly logging subsystem has a add-logging-api-dependencies configuration option that overrides the logging APIs contained in your application with global libraries.
In your particular case log4j:log4j is replaced with the JBoss Log4j Emulation, which forwards all logging events to JBoss Log Manager.
The thread dumps you posted do not show any indications of a deadlock. JBoss Log Manager is simply not able to deliver all logs in a timely fashion. Therefore you can:
Remark: The fact that your application uses Log4j 1 to log events should not have an influence on your problem. Nevertheless you should consider rewriting it in terms of a maintained logging API: Apache Commons Logging, Log4j 2 API or SLF4J for example. All these choices will enable you to swiftly change the logging implementation of your application without rewriting your code again.
To migrate to Log4j 2 API, see Migrating from Log4j 1 API to Log4j 2 API.