jdbc cancel mysql_关于jdbc的setQueryTimeout() 的bug和Query execution was interrupted 的调查

1、前段时间，两次开发人员提出，程序的日志里出现以下JDBC异常，当时排查MySQL数据库端在程序抛出异常时间并无异常；MySQL数据库也没有自动强制中断连接的设置，猜想是由程序的DAO层

设置的运行超时，当执行超过设置秒数，就会强制杀掉连接。

java.sql.SQLException : Query execution was interrupted

at com.mysql.jdbc.SQLError.createSQLException( SQLError.java:1055 )

2、昨天新斌提出MySQL端，是否有强制杀掉连接的设置，因为开发人员通过设置超时5S， 来删除了连接，但删除操作却执行了10s后返回，并抛出上面完成相同的异常。DAO有查询超时的设置， 只是依赖于mysql jdbc的Statement中的setQueryTimeout()来实现的。

【问题调查】

1、   调查为何超时设置的时间为5s, 为什么却执行10s， 虽然连接是强行中断的？

有两种可能：

1)可能dao设置的参数，没有正确传递到setQueryTimeout()方法中。

2)本身就是mysql jdbc的setQueryTimeout()的bug.

2、为了隔离问题，写个测试类，使用jdbc mysql直接数据库。

java大体语句：

String sql ="select * from account "; //查询语句，由于表很大，3秒肯定返回不了。

Statement st = conn.createStatement();

st.setQueryTimeout(3); //设置执行超时为3秒

st.execute(sql);

执行的结果：

查询超时设置长度：3秒

java.sql.SQLException : Query execution was interrupted

at com.mysql.jdbc.SQLError.createSQLException( SQLError.java:1055)

at com.mysql.jdbc.SQLError.createSQLException( SQLError.java:956)

----------------------省略部分----------------------------------

实际运行：5秒

结论： 从设置的超时3秒, 却运行了5秒中断返回。 所以这完全可以肯定是mysql jdbc的bug.

相关测试：凡事不带where条件的delete , select, update设置超时都不准确。

【超时设置的原理】

由于MySQL数据库本身没有对查询找连接超时的设置参数， wait_timeout设置的是sleep的时间超时。 那么jdbc是如何实现的？

验证方法：

打开mysql general log,然后再运行的java程序， 可以见到下面的log信息。

java程序连接执行Sql时，生成的连接的thread_id=13，然后会有另一个新的java线程连接进来，执行了kill 13的操作。

注意：任何用户哪怕只有select权限，也有kill 自己连接的权限。

MySQL JDBC Statement的QueryTimeout处理过程

1. 通过调用Connection的createStatement()方法创建statement

2. 调用Statement的executeQuery()方法

3. statement通过自身connection将query发送给MySQL数据库

4. statement创建一个新的timeout-execution线程用于超时处理

5. 5.1版本后改为每个connection分配一个timeout-execution线程

6. 向timeout-execution线程进行注册

7. 达到超时时间

6. TimerThread调用JtdsStatement实例中的TsdCore.cancel()方法

7. timeout-execution线程创建一个和statement配置相同的connection

8. 使用新创建的connection向超时query发送cancel query(KILL QUERY “connectionId”)

【总结】

以后开发再出现，java.sql.SQLException : Query execution was interrupted  这类异常信息，基本都可以定位为这类问题。