「十年饮冰」

深入分析JDBC超时机制

发表于 | 分类于 ， ， ， ， |

前言

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

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


不理解上面的排查步骤没关系，理解成一句话就是:一个数据库操作的线程一直处于runable状态但是一直hand住没有返回值

通过jstack的信息，可以发现是我们的一个事务在执行conn,setAutoCommit(true)时，一直在native方法read…长时间read。我们有设置超时时间，但是为什么这里会没有超时呢（发现时线程大概运行了有20min）？？？。咨询DBA同事定位问题之后，大概得出是因为我们没有设置socketTimeout。如果没有设置socketTimeout将会依赖OS底层的timeout，线上大概是30min。虽然通过DBA同事的经验解决了问题，但是仍然存在疑问，为什么mysql存在两种timeout机制呢？queryTimeout和socketTimeout？socketTimeout难道不应该是queryTimeout的子集？queryTimeout应该也能发现我们的Sql超时了啊？

这就和JDBC的实现机制有关系了，为什么会有两种Timeout机制的存在。用一种超时不能解决问题吗？

JDBC执行SQL的原理

这个名词也就是queryTimeout，他是属于应用层面的timeout机制。用来控制我们sql语句执行的时间的超时，但是mysql并没有用他来发现所有的问题。下面摘抄一段Statement执行SQL的代码片段

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43

CancelTask timeoutTask = null;//实现statementTimeout的timer。每一个SQL执行都会创建一个
 
try {
    //有超时设置会初始化这个timer
    if (locallyScopedConnection.getEnableQueryTimeouts() && this.timeoutInMillis != 0 && locallyScopedConnection.versionMeetsMinimum(5, 0, 0)) {
        timeoutTask = new CancelTask(this);
        locallyScopedConnection.getCancelTimer().schedule(timeoutTask, this.timeoutInMillis);
    }
 
    if (!isBatch) {
        statementBegins();
    }
    //执行SQL（sync）
    rs = locallyScopedConnection.execSQL(this, null, maxRowsToRetrieve, sendPacket, this.resultSetType, this.resultSetConcurrency,
            createStreamingResultSet, this.currentCatalog, metadataFromCache, isBatch);
 
    if (timeoutTask != null) {
        timeoutTask.cancel();
 
        locallyScopedConnection.getCancelTimer().purge();
 
        if (timeoutTask.caughtWhileCancelling != null) {
            throw timeoutTask.caughtWhileCancelling;
        }
 
        timeoutTask = null;
    }
 
    synchronized (this.cancelTimeoutMutex) {
        if (this.wasCancelled) {
            SQLException cause = null;
            //如果是被timer kill，则抛出异常
            if (this.wasCancelledByTimeout) {
                cause = new MySQLTimeoutException();
            } else {
                cause = new MySQLStatementCancelledException();
            }
            resetCancelledState();
            //抛出
            throw cause;
        }
    }

Timer中的代码大致的意思就是copy一个和现在相同的connection，然后执行一条cancelStmt.execute(“KILL QUERY “ + CancelTask.this.connectionId); 语句给数据库,让数据库立刻停止这个链接的SQL

那么整个SQL执行的过程可以简单的描述如下：

  • 执行SQL之前给每一个执行SQL创建一个对应超时时间的Timer，到了时间之后会去kill这调语句
  • kill成功之后，数据库会立即返回一个result，也就是上面代码执行SQL语句的返回值
  • 正常执行语句，抛出超时异常

这里值得注意的地方，为什么不直接用StatementTimeout直接发现超时，然后返回，不用管rs的结果到底是什么。为了防止超长时间的SQL在server端执行，JDBC在发现自己的statement超时之后，会发一个kill指令给server，那么这个server指令有超时时间吗？有timer吗？在最开始我们代码hang住的setAutoCommit（）指令有timer吗？
没有！！！！

下面是通过jprofiler分别执行statement和执行setautoCommit两个指令的内存状态图，可以发现，后者是没有timer对象的（第二张），而前者有(第一张)！！！因为后者的代码根本就没有创建timer逻辑的部分。可以在源码里面看到后者会直接就调用底层的connectionImpl的execSQL方法执行SQL

但是kill是通过copy链接来发送kill命令的。会有timer吗?下图是在发送kill指令时，用debug可以看到,kill 指令发送的时候statementTimeout是0，是不会创建TImer的 ，第一张图是在执行Statement SQL的，超时时间是我们设置的2s，第二张图是执行kill指令时的，可以发现超时时间是0，不会创建timer。仔细想想也能明白，如果kill指令也有timer，逻辑和statement sql一样，那岂不是会无限循环！！

证明

第一种

socketTimeout设置得比StatementTimeOut小为1s，后者为5s执行如下语句:

1
2
3
4
5
6
7
8
9
10
11
<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource" init-method="init" destroy-method="close">
       <!-- 基本属性 url、user、password -->
       <property name="url" value="jdbc:mysql://127.0.0.2:3306/my?socketTimeout=1000"/>
       <property name="username" value="root" />
       <property name="password" value="123456" />
       <property name="queryTimeout" value="5"/>
        //省略
 
</bean>
//sql 10s之后返回数据
select sleep(10) ,name from user where id=1

会在1s之后得到如下结果，看起来很正常，在timer没有发起kill之前，因为socket没有得到数据所以socket超时了，这一点提醒我们，设置socket超时一定要比statement长，不然你设置得statement超时将毫无意义

1
2
3
4
The last packet successfully received from the server was 1,057 milliseconds ago.  The last packet sent successfully to the server was 1,012 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45

第二种

把statement设置为2s，socketTime设置成6s。会在2s之后得到如下输出。如果socketTime设置成比statement大，那么在后者超时之后，会去kill掉SQL之后立马返回抛出异常

1
2
3
com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
    at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1390)
    at com.alibaba.druid.pool.DruidPooledStatement.executeQuery(DruidPooledStatement.java:140)

第三种

和第二种相同的情况，把statement的超时设置成5s，socket超时设置成15s。但是我会在发起kill之前把网络给断掉，来模拟出现网络问题，或者server直接down掉的情况。会在15s后得到一下结果

1
2
3
4
The last packet successfully received from the server was 15,003 milliseconds ago.  The last packet sent successfully to the server was 15,004 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

为什么是15s后呢？为什么不是statement的超时的时间呢？这就和上面JDBC源码部分有关系了。从上面的代码可以看出，rs必须返回之后才会抛出异常，当rs不返回时不会继续往下走的。rs什么时候返回？关于kill query什么时候返回，在网上找的一些资料 https://dev.mysql.com/doc/refman/5.7/en/kill.html

kill命令详解

注：只针对innodb引擎

mysql KILL QUERY只abort线程当前提交执行的操作，其他的保持不变，并且db server报SQL 语法异常（You have an error in your SQL syntax）。
根据当前被kill的statement是否在事务中，分两种情况分析：

  • (1) 不在事务中（未显式开启）
    innodb中statement具有原子性。因此kill掉后，会导致statement abort，回滚掉。

  • (2) 在事务中

    • 假设事务中sql执行顺序是sql1;sql2;sql3; 在执行sql2时被kill掉，则sql2会抛出异常，并且sql2执行失败。但是sql3依旧会执行下去。此时如果在spring层做了事务回滚处理，会对三条sql全部回滚掉。

    • sql抛出的异常时MySQLSyntaxErrorException，我们会看到它是受检异常，但是我们了解spring默认是只对非受检异常做回滚处理的，怎么会这样呢？是框架对其做了转化，最终转为非受检异常，spring事物管理器就可以对其做回滚处理了。

mysql收到kill query后执行时机

KILL操作后，该线程上会设置一个特殊的 kill标记位。通常需要一段时间后才能真正关闭线程，因为kill标记位只在特定的情况下才检查。具体时机是

  • 执行SELECT查询时，在ORDER BY或GROUP BY循环中，每次读完一些行记录块后会检查 kill标记位，如果发现存在，该语句会终止；
  • 执行ALTER TABLE时，在从原始表中每读取一些行记录块后会检查 kill 标记位，如果发现存在，该语句会终止，删除临时表；
  • 执行UPDATE和DELETE时，每读取一些行记录块并且更新或删除后会检查 kill 标记位，如果发现存在，该语句会终止，回滚事务，若是在非事务表上的操作，则已发生变更的数据不会回滚；
  • GET_LOCK() 函数返回NULL；
  • INSERT DELAY线程会迅速内存中的新增记录，然后终止；
  • 如果当前线程持有表级锁，则会释放，并终止；
  • 如果线程的写操作调用在等待释放磁盘空间，则会直接抛出“磁盘空间满”错误，然后终止；
  • 当MyISAM表在执行REPAIR TABLE 或 OPTIMIZE TABLE 时被 KILL的话，会导致该表损坏不可用，指导再次修复完成。

所以，当kill query这条指令发送过去的时候，由于网络问题一直没响应，会等到socketTimeout之后，整个SQL语句的执行才会返回。所以socketTimeout也不宜设置得太长，在网络不好的时候超时时间基本上不会是statementTimeout的时长。这也就证明了jstack中的问题，那一时刻出现了网络问题，到时setAutoCommit这条指令被卡住，由于没有设置socket超时，得依赖os底层的socket超时时间30min，其实如果我们不重启服务，相信30min钟后服务会自愈。
最好大家自己执行一下上面三种情况，就能很快理解

总结

  • StatementTimeout主要是为了限制我们执行SQL语句的时长，由于设计问题并不能包含所以超时情况
  • 除了用户自己写的SQL，其他的SQL指令依赖的超时时间都是socket超时。例如执行事务时的setAutoCommit和statement执行SQL超时时执行的kill query指令
  • 可不可以只设置socket超时？最好不要，如果这样的话会导致mysql server有大量长时间运行的SQL(没有被超时kill)
  • socketTimout一定要设置得大于statementTimeout，不然设置后者将会没有任何意义
  • 一个SQL就会有一个timer的产生，这一点以前是不知道的，以为都是依赖的底层超时

资料

http://imysql.com/2014/08/13/mysql-faq-howto-shutdown-mysqld-fulgraceful.shtml
http://www.importnew.com/2466.html
https://dev.mysql.com/doc/refman/5.7/en/kill.html

谢照东 wechat
欢迎您扫一扫上面的微信公众号，订阅我的博客！
坚持原创技术分享，您的支持将鼓励我继续创作！