前言
上周在線上出現出現報警，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的產生，這一點以前是不知道的，以為都是依賴的底層超時
到此這篇關于JDBC超時機制的文章就介紹到這了,更多相關JDBC超時機制內容請搜索服務器之家以前的文章或繼續瀏覽下面的相關文章希望大家以后多多支持服務器之家！
資料
- 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
原文鏈接：https://zhuanlan.zhihu.com/p/28308813
