上周在线上出现出现报警,ID号码一直无法获取,但是只有这一台机器报警,所以第一时间先在服务治理平台上禁用掉这台机器保证服务正常。停掉机器后要排查问题,思考分析步骤如下:
"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机制的存在。用一种超时不能解决问题吗?
这个名词也就是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执行的过程可以简单的描述如下:
这里值得注意的地方,为什么不直接用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
注:只针对innodb引擎
mysql KILL QUERY只abort线程当前提交执行的操作,其他的保持不变,并且db server报SQL 语法异常(You have an error in your SQL syntax)。
根据当前被kill的statement是否在事务中,分两种情况分析:
mysql收到kill query后执行时机
KILL操作后,该线程上会设置一个特殊的 kill标记位。通常需要一段时间后才能真正关闭线程,因为kill标记位只在特定的情况下才检查。具体时机是
所以,当kill query这条指令发送过去的时候,由于网络问题一直没响应,会等到socketTimeout之后,整个SQL语句的执行才会返回。所以socketTimeout也不宜设置得太长,在网络不好的时候超时时间基本上不会是statementTimeout的时长。这也就证明了jstack中的问题,那一时刻出现了网络问题,到时setAutoCommit这条指令被卡住,由于没有设置socket超时,得依赖os底层的socket超时时间30min,其实如果我们不重启服务,相信30min钟后服务会自愈。
最好大家自己执行一下上面三种情况,就能很快理解