一文深入解析JDBC超时机制

一文深入解析JDBC超时机制

目录前言JDBC执行SQL的原理证明kill命令详解总结资料

前言

上周在线上出现出现报警，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-.SocketInputStream.socketRead0(Native Method)

at java-.SocketInputStream.socketRead(SocketInputStream.java:116)

at java-.SocketInputStream.read(SocketInputStream.java:170)

at java-.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的代码片段

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执行如下语句:

//省略

//sql 10s之后返回数据

select sleep(10) ,name from user where id=1

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

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之后立马返回抛出异常

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后得到一下结果

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时，每读取http://一些行记录块并且更新或删除后会检查 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的产生，这一点以前是不知道的，以为都是依赖的底层超时

版权声明：本文内容由网络用户投稿，版权归原作者所有，本站不拥有其著作权，亦不承担相应法律责任。如果您发现本站中有涉嫌抄袭或描述失实的内容，请联系我们jiasou666@gmail.com 处理，核实后本网站将在24小时内删除侵权内容。