WildFly高负载下日志线程引发大量线程阻塞的优化方案咨询

我们团队的Java Web应用基于WildFly 9.0.1搭建，日志组件选用的是log4j-1.2.17.jar。最近在高负载场景下，应用出现了CPU占用过高、甚至无响应的情况，给业务带来了不小的影响。

通过分析线程dump文件，我们定位到问题根源：大量业务线程处于BLOCKED状态，而阻塞它们的源头是一个日志相关线程，前后一共堵了近100个线程。

阻塞源线程的栈信息 #

"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)

被阻塞的业务线程栈示例 #

"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)

目前我们已经查阅了一些技术资料，知道升级Log4j版本是一个可能的解决方向，但我们想了解：除了升级组件之外，还有哪些配置调整或者代码层面的优化可以避免这类线程阻塞问题呢？

麻烦各位大佬指点迷津，感谢大家的关注！

备注：内容来源于stack exchange，提问作者mcacorner