Java多线程中程序阻塞问题排查过程

背景说明：

    市场反馈说数据投产功能速度太慢，需要优化，决定使用并发投产的方式，于是启用了线程池技术。但是市场在用的时候会出现项目卡死不动的情况。数量少的时候不会出现，数据量大就会出现，项目日志也停滞不前。

    线程池参考：线程池之ThreadPoolExecutor概述和线程池之ThreadPoolExecutor使用

问题原因：

    数据库连接池连接数不够用的缘故导致。

解决过程：

    造成这个问题的原因很简单，但是解决问题的过程过程还是很艰难的，从中我还是get了很多的新技能，在此总结记录一下。

一、问题复现：

    由于涉及的代码逻辑很长，而且涉及到三个平台，在A平台开启多线程，并发调用B平台的接口，B平台会进行一系列操作，在开发阶段，B平台数据入库就出现过死锁问题，而且B要调用C平台的接口。由于涉及的平台较多，所以发现问题很困难。不过最后还是定位到B平台的问题。

二、查看线程dump：

    由于才开始编写多线程的程序，对这里面的一些东西很陌生，这个是造成处理问题艰难的最大原因。

   多线程情况下，由于程序卡死，要想知道为什么会卡死当然需要知道线程堆栈内的内容，看看到底哪里出现了问题。经过一段摸索，终于让我找到了一个神器：JVisualVM，一开始我还从官网上下载，而且是英文版的，想想就害羞，因为这个工具是jdk自带的，在jdk的bin目录里面就有，而且是中文版的。除此之外，jdk里面还有jconsole工具，效果没有JVisualVM好。以下是界面：

怎么用就不说了，自行百度。

    找到了这个工具还是不行，只能看到有很多线程都被阻塞了，但是看不到原因，经过一番努力，其实很简单，这个工具上就有：

这就可以直接看到线程阻塞堆栈了。

获取线程dump日志除了通过VisualVM之外，还可以通过指令来获取：通过进程号获取线程dump日志，文件存储路径在Windows/System32下面，这样就可以脱落工具直接查看线程问题了。可参考：获取java线程dump文件

jstack 进程ID -l >> dunmp文件.txt

二、定位问题：

    获取到线程的dump文件了还是一脸懵逼，因为对这个里面的信息感到很陌生，出现了大量的以下信息，也就是有很多线程都被阻塞住了：

"http-bio-8090-exec-43" #67 daemon prio=5 os_prio=0 tid=0x000000001dc14000 nid=0x2444 in Object.wait() [0x000000002d26b000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1115)
	- locked <0x00000007863487b0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Latch)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
	at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
	at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:450)
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:450)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:427)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:276)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
	at com.sun.proxy.$Proxy55.getInstancesHasFromCluster(Unknown Source)
	at awb.operations.webService.group.A_GroupMgrService.restartGroup(A_GroupMgrService.java:614)
	at awb.operations.controller.group.GroupController.restartGroup(GroupController.java:265)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
	at cn.com.agree.aweb.core.escape.EscapeSupportedServletInvocableHandlerMethod.invokeForRequest(EscapeSupportedServletInvocableHandlerMethod.java:72)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:110)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:817)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:731)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:968)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:870)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:650)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:844)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at cn.com.agree.aweb.core.filter.AfaResourceFilter.doFilter(AfaResourceFilter.java:49)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at cn.com.agree.aweb.asapi.filters.SimpleParameterEscapeFilter.doFilter(SimpleParameterEscapeFilter.java:50)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at cn.com.agree.aweb.core.filter.CharsetEncodingFilter.doFilter(CharsetEncodingFilter.java:49)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at cn.com.agree.aweb.asapi.filters.ASAPIFilter.doFilter(ASAPIFilter.java:68)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
	- locked <0x00000007b59b2d90> (a org.apache.tomcat.util.net.SocketWrapper)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- <0x00000007854ff4c0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

一开始根据这个信息我还是没有看出到底什么原因，隐约感觉到是spring开启事务的时候引起的报错，经过一番努力，终于在这篇博客中遇到同样的问题：解决dbcp2线程池GenericObjectPool.borrowObject阻塞问题

他遇到的问题和我的很像，但是也有些许的不同：

"http-bio-8090-exec-43" #67 daemon prio=5 os_prio=0 tid=0x000000001dc14000 nid=0x2444 in Object.wait() [0x000000002d26b000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1115)
	- locked <0x00000007863487b0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Latch)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
	at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)

原因就是他用的是dbcp2，而我用的是dbcp，Tomcat的版本不同，Tomcat7用的是dbcp，而8.5和9用的是dbcp2，虽然版本不一样，但是问题的根源都是一样的，那就是数据库连接数不够线程数。

  以为跟着他写的设置了 maxTotal="-1"，但是启动报错，原因还是dbcp的版本问题，dbcp2将之前的maxActive和maxWait改成了maxTotal和maxWaitMillis：关于tomcat启动时的警告 ：Property maxActive is not used in DBCP2, use maxTotal instead. 和 Property maxWait i

  由于我用的是Tomcat7，用的是dbcp，所以应该设置maxActive="-1"（连接数无限），大功告成！！！

总结：

  对于多线程的恐惧使我走了不少弯路，遇到问题不应该一直重复测试、复现，而应该找到问题的根节所在，才能高效处理问题。另外就是需要增加对于Java调优方面的学习，不能一直浮于表面