深入分析JDBC超时机制

版权声明: https://blog.csdn.net/a837199685/article/details/75796891

前言

上周在线上出现出现报警,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

这里写图片描述
这里写图片描述

不理解上面的排查步骤没关系,理解成一句话就是:一个数据库操作的线程一直处于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执行如下语句:

<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超时将毫无意义

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时,每读取一些行记录块并且更新或删除后会检查 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

展开阅读全文

没有更多推荐了,返回首页