深入分析JDBC超时机制

前言

上周在线上出现出现报警，ID号码一直无法获取，但是只有这一台机器报警，所以第一时间先在服务治理平台上禁用掉这台机器保证服务正常。停掉机器后要排查问题，思考分析步骤如下:

• 通过监控发现只有一个key的ID调用发生下降（第一张），这台机器上的其他key没有任何问题，从数据库更新号段正常。是不是数据库死锁了？
• 这个key在其他机器更新key是正常的，排除数据库的问题，那么就是这台机器的问题
• 查看log，发现这台机器确实没有更新数据库，两个号段的buffer都是空的。为什么更新数据库失败呢？难道是大量的超时？
• 仔细检查log日志，发现并没有超时的error。首先没有超时，但是号段是null的，是不是线程的问题？难道是代码逻辑有问题？
• 理了一遍逻辑发现代码逻辑没有问题，那是线程卡住了？
• 马上抓几次jstack log。果然发现有一条更新线程一直处于runable状态（第二张），其他线程池里面的线程都是waiting状态（禁用了服务，没有请求不会更新).
• 确定是线程一直卡住了，先重启这台机器，保证dx机房有两台机器工作。
• jstack的栈如下

"Thread-Segment-Update-4" daemon prio=10 tid=0x00007f2c6000c000 nid=0x2455 runnable [0x00007f2c55deb000]
  java.lang.Thread.State: RUNNABLE
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
   at java.net.SocketInputStream.read(SocketInputStream.java:170)
   at java.net.SocketInputStream.read(SocketInputStream.java:141)
   at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
   at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143)
   at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173)
   - locked com.mysql.jdbc.util.ReadAheadInputStream@33d807d4
   at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2911)
   at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3332)
   at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3322)
   at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3762)
   at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
   at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
   at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2531)
   - locked com.mysql.jdbc.JDBC4Connection@178ec6c
   at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4852)
   - locked com.mysql.jdbc.JDBC4Connection@178ec6c