tomcat线程被打满怎么排查_记一次JDBC并发加载导致死锁的排查过程

背景

之前在支持业务团队组件升级时，发现生产环境有个应用健康检查一切正常，一旦拉入流量后应用就无法访问。在应用无响应时，Java进程仍然活着，应用所属容器的CPU、内存等指标也未发现任何异常。最终经过排查，问题的原因为JDBC Driver加载时死锁导致。下面将整个排查步骤做一个总结，为大家以后排查类似问题提供一点思路。

堆栈分析

由于应用无响应，首先想到的是查看所有线程堆栈信息。下面是通过监控系统获取的堆栈信息片段：

通过堆栈信息可以发现，大量tomcat请求处理线程都阻塞在获取数据库连接连接这一步。由于获取DB连接迟迟没有返回，最终导致tomcat线程池达到最大线程数，对后续请求无响应。健康检查接口正常是因为只是简单返回了OK，并没有数据库访问，所以拉入流量之前健康检查是正常的。
看到DB连接阻塞，第一个想到的是DB连接数过多从而拒绝连接，但是经过DBA协助排查，发现DB一切正常，而且使用其它客户端连接DB也毫无问题。
既然问题不是出在DB上，只能回头再次查看堆栈信息，经过对所有tomcat线程归类，发现该应用使用了两种连接池实现：Alibaba Druid和tomcat-jdbc，都是用来连的MySQL数据库。

Druid堆栈分析

通过分析Druid连接DB的线程，除了其中一个线程，其它线程都阻塞在如下的点上：

"http-nio-8080-exec-10" #13 prio=5 os_prio=0 tid=0x000000001f26b800 nid=0x2ae0 waiting on condition [0x000000001fb2f000]   java.lang.Thread.State: WAITING (parking)        at sun.misc.Unsafe.park(Native Method)        - parking to wait for  <0x000000076c275960> (a java.util.concurrent.locks.ReentrantLock$FairSync)        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireInterruptibly(AbstractQueuedSynchronizer.java:897)        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1222)        at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)        at com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:732)        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1222)        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1218)        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90)        ...

而唯一一个例外的线程如下：

"http-nio-8080-exec-03" #19 prio=5 os_prio=0 tid=0x000000001f276000 nid=0x3a9c in Object.wait() [0x000000002012c000]   java.lang.Thread.State: RUNNABLE        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)        at java.lang.Class.newInstance(Class.java:442)        at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)        at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)        at java.util.ServiceLoader$1.next(ServiceLoader.java:480)        at java.sql.DriverManager$2.run(DriverManager.java:603)        at java.sql.DriverManager$2.run(DriverManager.java:583)        at java.security.AccessController.doPrivileged(Native Method)        at java.sql.DriverManager.loadInitialDrivers(DriverManager.java:583)        at java.sql.DriverManager.(DriverManager.java:101)        at com.alibaba.druid.proxy.DruidDriver.registerDriver(DruidDriver.java:92)        at com.alibaba.druid.proxy.DruidDriver$1.run(DruidDriver.java:84)        at java.security.AccessController.doPrivileged(Native Method)        at com.alibaba.druid.proxy.DruidDriver.(DruidDriver.java:81)        at com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:745)        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1222)        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1218)        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90)        ...

通过以上的堆栈信息发现，因为并发的原因，所有线程都调用的DruidDataSource.init()来初始化线程池，理论上只有一个线程会真正做初始化操作，所以大部分线程在等待锁。可以看下DruidDataSource.init()的源代码：

    public void init() throws SQLException {        if (inited) {            return;        }        final ReentrantLock lock = this.lock;        try {            //尝试获取初始化锁            lock.lockInterruptibly();        } catch (InterruptedException e) {            throw new SQLException("interrupt", e);        }        boolean init = false;        try {            //获取到锁后Double-Check状态位            //如果已初始化完成则直接返回            if (inited) {                return;            }            initStackTrace = Utils.toString(Thread.currentThread().getStackTrace());            this.id = DruidDriver.createDataSourceId();            //初始化线程池            ...            ...        } catch (Error e){            LOG.error("{dataSource-" + this.getID() + "} init error", e);            throw e;        } finally {            inited = true;            lock.unlock();            ...            ...        }    }

从源码中得知，每个DruidDataSource通过一个ReentrantLock和一个状态位来保证init()操作只会进行一次。所以，在线程堆栈中，只有一个线程进入最终的DriverManager的初始化阶段。现在的问题就是得到锁的这个线程阻塞在DriverManager的初始化阶段。原因稍后分析，先来看堆栈里另外一个线程池的状态。

Tomcat-Jdbc堆栈分析

跟Druid线程池有点像，tomcat-jdbc连接池除一个线程外，其它线程阻塞在如下的点上：

"http-nio-8080-exec-13" #23 prio=5 os_prio=0 tid=0x000000001f283000 nid=0x541c in Object.wait() [0x000000002052f000]   java.lang.Thread.State: RUNNABLE        at java.lang.Class.forName0(Native Method)        at java.lang.Class.forName(Class.java:348)        at org.apache.tomcat.jdbc.pool.ClassLoaderUtil.loadClass(ClassLoaderUtil.java:38)        at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:271)        at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:203)        at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:735)        at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:667)        at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)        at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:131)        at com.ppdai.demo.datasource.ConcurrentDataSource$ConnectionTask.run(ConcurrentDataSource.java:150)        at java.lang.Thread.run(Thread.java:748)

而唯一一个例外的线程如下：

"http-nio-8080-exec-23" #24 prio=5 os_prio=0 tid=0x000000001f286000 nid=0x4fd8 in Object.wait() [0x000000002062e000]   java.lang.Thread.State: RUNNABLE        at com.mysql.jdbc.Driver.(Driver.java:49)        at java.lang.Class.forName0(Native Method)        at java.lang.Class.forName(Class.java:348)        at org.apache.tomcat.jdbc.pool.ClassLoaderUtil.loadClass(ClassLoaderUtil.java:38)        at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:271)        at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:203)        at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:735)        at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:667)        at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)        at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:131)        at com.ppdai.demo.datasource.ConcurrentDataSource$ConnectionTask.run(ConcurrentDataSource.java:150)        at java.lang.Thread.run(Thread.java:748)

从以上的堆栈信息可以看出，在并发的通过tomcat-jdbc连接池获取连接时，会先通过Class.forName()来加载驱动类。由于类加载器(ClassLoader)在加载类时会使用synchronized互斥锁，所以同样只有一个线程会进入到com.mysql.jdbc.Driver.,因为这个线程一直没有释放锁，所有其它线程就只能一直等待下去。
从以上对两个线程池的堆栈分析可以得出结论，因为两个获取到锁的线程分别被阻塞在DriverManager和Driver的方法，导致整个web server的所有线程被BLOCK住。所以剩下的工作就是分析下为什么并发加载这两个类会导致死锁。在查找死锁原因之前，先简单回顾下方法的作用及JDBC驱动的加载原理。

类加载过程

按照JVM虚拟机规范，一个类在被使用前必须先被加载。平常代码中第一次用new初始化类的一个实例或者调用一个类的static方法都属于类被使用的情况。一个类的加载过程可以分为加载class字节码、连接和初始化3个步骤。其中，在初始化这一步中会初始化static成员变量的值和执行static{}包围的代码块，这部分逻辑封装在方法中。该方法是在编译时自动加入class文件中的，并且虚拟机保证该方法是synchronized的。

JDBC驱动加载原理

Java对数据库的访问通过JDBC框架定义的一系列接口来实现，不同的数据库产品提供自己专属的JDBC Driver实现。用户程序中要连接数据库(比如MySQL)，有如下两种方式:

• 一种是直接初始一个MySQL的Driver，调用它的connect()方法。比如 new com.mysql.jdbc.Driver().connect(url, properties);
• 第二种是使用java.sql.DriverManager.getConnection(url, username, password); DriverManager会自动遍历classpath中所有Driver实现类，选择支持该url的实现来建立连接，这里面对实现类的查找使用的Java的SPI机制。

无论应用中采用的哪种连接池实现，最终都是靠以上两种方式的一种来建立连接的。
对于具体的数据库JDBC实现，除了要满足SPI的要求，JDBC框架其实还有一个规定，就是Driver的实现类在被加载时，需要主动将自己的一个实例注册到DriverManager。也就是说只要调用了Class.forName("com.mysql.jdbc.Driver");加载类的同时，mysql Driver会同时初始化一个实例注册到DriverManager。

死锁过程

了解完类和JDBC加载之后，再来看下上面的堆栈，就知道我们只需要看DriverManager.和com.mysql.jdbc.Driver.分别干了什么就可以知道死锁的原因了。
首先来看Druid的堆栈，线程获取到lock之后开始init，会调用DriverManager.registerDriver(driver)方法，因此触发的了DriverManager类的加载，类加载过程中调用，运行如下static{}代码块：

  public class DriverManager {    ...    static {        loadInitialDrivers();        println("JDBC DriverManager initialized");    }    ...  }

方法loadInitialDrivers()的源码就不贴了，里面的逻辑就是使用ServiceLoader按java的SPI约定加载所有JDBC驱动类，然后初始化Driver实例。这时候自然就尝试加载com.mysql.jdbc.Driver类。
在Druid加载DriverManager的同时，tomcat-jdbc也在做初始化的工作，从堆栈中可以看出，它采用的获取连接的方式恰好是采用的另外一种，直接使用Class.forName("com.mysql.jdbc.Driver")加载类，这时候看下这个类的static{}代码块：

  public class Driver extends NonRegisteringDriver implements java.sql.Driver {    static {        try {            java.sql.DriverManager.registerDriver(new Driver());        } catch (SQLException E) {            throw new RuntimeException("Can't register driver!");        }    }    public Driver() throws SQLException {        // Required for Class.forName().newInstance()    }}

MySQL的Driver实现里按照JDBC框架的要求在类初始化时注册实例到DriverManager。
这个时候在Druid的线程中持有DriverManager.的互斥锁，然后等待com.mysql.jdbc.Driver.的互斥锁。而tomcat-jdbc的线程恰好相反，它持有com.mysql.jdbc.Driver.的互斥锁，而等待DriverManager.的互斥锁，由此导致死锁的发生。
这也解释了为什么这个故障是偶发性的，因为该应用是依赖Spring来初始化DataSource的，Spring初始化时不是每次都会并发的初始化这个两个Bean，只要有一个稍微提前一点，这个问题就不会出现。

解决方案

通过上面的分析可以得知，本文所说的应用故障原因就是因为使用了两个不同连接池来访问数据库。由于这两个连接池初始化JDBC Driver和建立连接采用的方式有区别，导致并发情况下死锁的发生。对于该应用面临的问题可以选用下面任意一种方案来解决：

• 只采用一种连接池产品，这个是最简单直接的方式。
• 如果应用改造代价较大，可以通过提前加载JDBC驱动的方式来解决。比如在main()函数的第一行添加Class.forName("com.mysql.jdbc.Driver")。这样，在连接池初始化时就无需再加载驱动类了。
• 如果是使用Spring等容器初始化的连接池，也可以通过让连接池顺序初始化来解决并发问题，比如使用Spring的@DependsOn注解。当然这种方法有点取巧，对以后的维护性也不太友好，不是很建议采用。

问题扩展

问题虽然解决了，我们来扩展一下思路。上面的应用是不同的连接池都是连的MySQL，如果我们采用同一个连接池，来连两个不同类型的数据库，比如一个MySQL，一个SQL Server，会不会有问题呢？
答案是有可能，具体要看使用的是哪个连接池。

• 如果是Druid，不会。
  因为它在初始化的时候先加载的DriverManager，无论classpath下面有几种JDBC的Driver，都会被加载。所以，即使有并发，因为DriverManager初始化是有互斥锁保护的，不会有问题。
• 如果是tomcat-jdbc，会。
  因为它会先使用Class.forName()初始化驱动类，并发的情况下一个线程加载MySQL Driver，该Driver会调用DriverManager类注册自己，而DriverManager类又会尝试加载classpath下SQL Server的驱动类。这时候，另外一个线程正好在加载SQL Server的驱动类，就会造成死锁。
  如果使用tomcat-jdbc连接池，下面的代码可以重现这个问题。

public class ConcurrentDataSourceTest {    private static DataSource initMySQLDataSource() {        ...     }    private static DataSource initSqlServerDataSource() {        ...     }    public static void main(String[] args) throws Exception {      //初始化tomcat-jdbc dataSource      DataSource mysqlDataSource = initMySQLDataSource();      DataSource sqlserverDataSource = initSqlServerDataSource();      //使用Phaser是为了让所有线程准备好后同时开始建立连接      final Phaser phaser = new Phaser(1);      //每个dataSource用10个线程并发开启10个连接，便于问题重现      for(int i=0; i< 10; i++) {          phaser.register();          new Thread(() -> {              phaser.arriveAndAwaitAdvance();              try (Connection connection = mysqlDataSource.getConnection()){                  System.out.println("Get Connection success");              } catch (SQLException e) {                  e.printStackTrace();              }          }).start();      }      for(int i=0; i< 10; i++) {          phaser.register();          new Thread(() -> {              phaser.arriveAndAwaitAdvance();              try (Connection connection = sqlserverDataSource.getConnection()){                  System.out.println("Get Connection success");              } catch (SQLException e) {                  e.printStackTrace();              }          }).start();      }      phaser.arriveAndDeregister();  }}

上面的程序启动后，不会打印"Get Connection success"，证明被阻塞住。

注意：在初始化连接池时如果不设置driverClassName属性的值，则没有问题。但是，tomcat-jdbc会打印错误日志让设置这个属性。不设置就没问题的原因，留给读者去读一下它的源码就明白了。

总结

一个初始化数据库连接的动作涉及到类加载和spi等不少Java的基础知识。以上问题的原因分析对我们写代码也有一定的帮助，就是在代码中如果出现两个类循环依赖的情况，不要在类的static变量和代码块中互相引用。
类似下面的代码，应该尽量避免。否则，在并发情况下很容易出问题，而且在测试环境很难被发现。

public class ClassA {    private static ClassB classB = new ClassB();}  public class ClassB {    private static ClassA classA = new ClassA();}

作者介绍

chilexun， 信也科技基础组件资深研发，目前负责分布式任务调度及微服务相关中间件的研发及维护