知识库

客户OA系统上线第一天，单点aas设置了最大工作线程数1000，运行一段时间后，系统开始相应缓慢，打印堆栈后，发现工作线程状态如下：

"http-listener-1(936)" #28629 daemon prio=5 os_prio=0 tid=0x0000fff080067800 nid=0x345071 waiting on condition [0x0000ffeb645fc000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000fff340a9db48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2045)
    at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:350)
    at com.apusic.aas.logging.ApusicLogManager$PushThread.enqueue(ApusicLogManager.java:97)
    at com.apusic.aas.logging.ApusicLogManager.publish(ApusicLogManager.java:40)
    at com.apusic.aas.logging.ApusicLogManager$LazyLogger.log(ApusicLogManager.java:177)
    at com.apusic.aas.logging.ApusicLogManager$LazyLogger.log(ApusicLogManager.java:198)
    at com.sun.common.util.logging.LogPrintStream.println(LogPrintStream.java:62)
    at org.apache.felix.gogo.runtime.threadio.ThreadPrintStream.println(ThreadPrintStream.java:179)
    at com.excellence.explatform.webService.CountTimeOfServiceMethodInterceptor.invoke(CountTimeOfServiceMethodInterceptor.java:21)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at com.sun.proxy.$Proxy210.setWorkItemStatus(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor4432.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
    at org.springframework.remoting.support.RemoteInvocationTraceInterceptor.invoke(RemoteInvocationTraceInterceptor.java:77)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at com.sun.proxy.$Proxy210.setWorkItemStatus(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor4432.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)

通过堆栈可以看出都卡在记录日志的方法上，通过对日志模块的代码熟悉，发现日志模块是一个典型的“生产者-消费者”的使用模式：业务线程通过Logger接口写日志，写入的日志暂存于一个LinkedBlockingQueue中，AAS专门有一个线程从这个queue中拉取写入的日志，这个线程名是ApusicLogManager，然后交给ConsoleHandler和FileHandler处理；
上面的堆栈是业务调用了Logger接口导致卡住，由于LinkedBlockingQueue是一个有界queue，只要这个queue满了就会导致卡住，因此有可能是ApusicLogManager这个线程处理太慢导致卡住，但通过查看ApusicLogManager这个线程的堆栈，发现它卡在queue的take方法上，见截图2。也就是说生产者认为队列满了，消费者认为队列为空；
出现这种现象，第一反应就是jdk的LinkedBlockingQueue可能有bug，通过上网查阅这个queue是否曾经有人报过bug，并没有收获；然后仔细查阅源码，也没有发现可疑点；
后来让同事去现场dump了堆，通过mat分析堆，才终于找到原因：
1，首先，队列确实是满了，这点可以从mat分析得出；
2，通过查阅LinkedBlockingQueue代码可知，put的时候会通知卡在take方法上的线程，告诉它有数据来了；同样，take的时候也会通知卡在put上的线程，告诉它腾出了空间可以继续放数据了。现在看来是put的时候没有将通知发送到take线程，即ApusicLogManager线程（不是每次put都需要通知take线程，只有在queue为空后放入的第一条数据时才需要通知take线程）；
3，那什么情况下会导致put不通知呢？通过mat继续分析，在queue中发现了很有意思的信息：见第截图3。原来是抛了StackOverFlowError，且从第二行红线标记 的地方可以看出：正好抛在了put方法要通知take线程的地方，即还没来得及通知take线程就发生了错误。由于只有queue为空后put的第一条消息才会通知，后面即使再put也不会再通知，因此导致了take线程永远都不会被唤醒，然后put又一直在继续，直到把queue填满，然后导致Logger.log方法卡住；
4，那为什么会抛StackOverFlowError呢？通过继续查看queue里面的消息，发现是业务代码发生了无限递归，见截图4。其实在业务代码那里就已经抛了StackOverFlowError，但业务把它catch住了，然后开始记录日志，记日志的时候再一次抛了StackOverFlowError：此时该线程的栈空间已经快用完了，因此调用任何方法都有可能继续抛StackOverFlowError，只不过这个案例中正好抛在了LinkedBlockingQueue的put方法中。
5，其实从日志中也可以看到在别的地方也抛了StackOverFlowError，见截图5，不过在大多数方法中抛这个是无害的。

解决办法：

1、修改应用代码，避免函数无限递归造成的StackOverFlowError异常

2、临时处理办法，可以关闭aas的日志。日志不打印了，自然问题就不会触发。

3、可以尝试加大栈内存大小， -Xxs=10m。（此种办法对于无限递归的bug是无效的，依然会占满整个栈内存）

关键词： StackOverFlowError   日志  递归    ApusicLogManager  LinkedBlockingQueue