现象

在升级弹性数据库后，我们发现我们的应用在运行一段时候后，某些容器会收到服务端线程池满，并且一直不能恢复的情况。

线程为什么hang住了

在遇到线程问题时，我们首先想到的工具就是jstack。拿到拿到日志后，我们来一起看一下RPC有关的线程。

"RPC-BZ-22000-91-T-1" #419 daemon prio=5 os_prio=0 tid=0x00007f3dd8030800 nid=0x98b0a waiting on condition [0x00007f4169504000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c328b4f0> (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:2039)
	at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:1348)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1023)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:898)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4544)
	at com.alibaba.druid.filter.logging.LogFilter.dataSource_getConnection(LogFilter.java:827)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2724)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2724)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:661)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:880)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:872)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:97)
	at sun.reflect.GeneratedMethodAccessor338.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at net.bull.javamelody.JdbcWrapper$3.invoke(JdbcWrapper.java:781)
	at net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:294)
	at com.sun.proxy.$Proxy80.getConnection(Unknown Source)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
	at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:84)

日志很长，这里只截取了有关的部分，重点是: at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:1348), 这说明是获取数据库链接的时候阻塞住了。

Druid的链接怎么获取不了呢?

确定Druid状态的最好方法，无疑是Druid的控制台了。

从监控中可以看到Druid连接池的链接数量为0，证明当前是没有链接的。并且现象我们也可以推断是创建不出链接的。

到这里就需要讲一下Druid的链接创建方法了。

• Druid所有链接都是CreateConnectionThread创建出来的
• Druid在初始化的时候，会初始化三个内容:
  1. 定时调度的DestoryTask
  2. 一直运行的CreateConnectionThread
  3. 一直运行的DestoryConnectionThread, DestoryConnectionThread是用来逐出空闲线程的。
• init在Datasource初始化的时候并不会执行，是在第一次获取getConnection执行的。

如果线程创建不出来，那么我们就首先看一下CreateConnectionThread出了什么问题。

当我们再去翻jstack的日志时候，发现线程竟然找不到了！！

那我们就可以判断是CreateConnectionThread的退出，造成了获取不到数据库链接。

CreateConnectionThread为什么会退出呢?

CreateConnectionThread退出原因分析

1. 锁被打断

   try {
     lock.lockInterruptibly();
   } catch (InterruptedException e2) {
     break;
   }
   

   public DruidAbstractDataSource(boolean lockFair){
   	lock = new ReentrantLock(lockFair);
   
   	notEmpty = lock.newCondition();
   	empty = lock.newCondition();
   }
   

   这个锁是ReentrantLock我们可以理解为控制生产者，队列满了就不再生产。lockInterruptibly()方法我们从api可以看到只有当前线程被interrupt时才会出现这个情况。所以可以不用考虑。

2. 线程被中断

   catch (InterruptedException e) {
   	lastCreateError = e;
   	lastErrorTimeMillis = System.currentTimeMillis();
   
   	if (!closing) {
   		LOG.error("create connection Thread Interrupted, url: " + jdbcUrl, e);
   	}
   	break;
   }
   

3. 获取物理链接异常

   catch (SQLException e) {
   	LOG.error("create connection SQLException, url: " + jdbcUrl + ", errorCode " + e.getErrorCode()
                               + ", state " + e.getSQLState(), e);
   

4. 异常

   包括RuntimeException和Error。

理完了之后，就开干!

中断原因调查

1. 首先是打印druid的日志。

   <logger name="druid.sql" additivity="false">
               <appender-ref ref="sql_appender"/>
   </logger>
   <logger name="com.alibaba.druid.pool" additivity="false">
               <appender-ref ref="druid_appender"/>
   </logger>
   

   为什么一个是druid.sql一个是com.alibaba.druid.pool，这是因为LoggerFactory.getLogger给的参数不同。

2. 在运行一段时间后，成功观察到了线程中断的日志。

   2020-10-17 00:11:40.382 [Druid-ConnectionPool-Create-2072062363] ERROR com.alibaba.druid.pool.DruidDataSource - create connection Thread Interrupted, url: jdbc:mysql://xxx:3306/db_name?autoReconnect=true&useSSL=false
   .java.lang.InterruptedException: null
   	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
   	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048)
   	at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2752)
   

3. 这时候就碰到了问题，interrupt是观察到了，但是被谁interrupt了呢? 这里我们采用的方法是覆盖DruidDataSource类，在CreateConnectionThread中增加interrupt方法的复写。

   @Override
   public void interrupt() {
   	log.error("CreateConnectionThread线程被中断了!!!：thread={}, trace={}",Thread.currentThread().getName(),JSON.toJSONString(Thread.currentThread().getStackTrace()));
   	super.interrupt();
   }
   

4. 运行一段时间后，终于观察到了罪魁祸首！！！还是挺兴奋的

   2021-04-27 19:48:48.323 [ClusterManager] ERROR com.alibaba.druid.pool.DruidDataSource - CreateConnectionThread线程被中断了!!!：thread=ClusterManager, trace=[{"className":"java.lang.Thread","fileName":"Thread.java","lineNumber":1552,"methodName":"getStackTrace","nativeMethod":false},{"className":"com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread","fileName":"DruidDataSource.java","lineNumber":2720,"methodName":"interrupt","nativeMethod":false},{"className":"java.lang.ThreadGroup","fileName":"ThreadGroup.java","lineNumber":639,"methodName":"interrupt","nativeMethod":false},{"className":"com.xx.mq.client.consumer.GroupConsumer","fileName":"GroupConsumer.java","lineNumber":177,"methodName":"doStop","nativeMethod":false},{"className":"com.xx.registry.util.Service","fileName":"Service.java","lineNumber":122,"methodName":"stop","nativeMethod":false},{"className":"com.xx.registry.util.Closeables","fileName":"Closeables.java","lineNumber":118,"methodName":"close","nativeMethod":false},{"className":"com.xx.mq.client.consumer.TopicConsumer","fileName":"TopicConsumer.java","lineNumber":704,"methodName":"removeGroupConsumer","nativeMethod":false},{"className":"com.xx.mq.client.consumer.TopicConsumer$TopicClusterListener","fileName":"TopicConsumer.java","lineNumber":915,"methodName":"onEvent","nativeMethod":false},{"className":"com.xx.mq.client.consumer.TopicConsumer$TopicClusterListener","fileName":"TopicConsumer.java","lineNumber":898,"methodName":"onEvent","nativeMethod":false},{"className":"com.xx.registry.util.EventManager","fileName":"EventManager.java","lineNumber":309,"methodName":"publish","nativeMethod":false},{"className":"com.xx.registry.util.EventManager$EventDispatcher","fileName":"EventManager.java","lineNumber":433,"methodName":"run","nativeMethod":false},{"className":"java.lang.Thread","fileName":"Thread.java","lineNumber":745,"methodName":"run","nativeMethod":false}]
   

   从堆栈里去看到是因为com.xx.mq.client.consumer.GroupConsumer.doStop方法引起的，代码如下:

   @Override
   protected void doStop() {
     super.doStop();
     threadGroup.interrupt();
   

   我们可以看到它退出的时候，会使用threadGroup的方式进行退出。会把Group里所有的线程给退出。而Druid的初始化又是根据谁来获取Connection来定义的group，所以就会联动退出。

如何解决

解决的方式采取的是在初始化DruidDataSource后获取一下Connection，这样就不会受到mq线程的影响。

收获

1. 不要轻易使用ThreadGroup的方式去退出，因为java创建线程默认不指定的时候会获取父线程的Group。
2. 写代码要有基本的注释。在看Druid的代码很头疼，代码可读性很关键。