前言

上周在線上出現(xiàn)出現(xiàn)報警，ID號碼一直無法獲取，但是只有這一臺機器報警，所以第一時間先在服務(wù)治理平臺上禁用掉這臺機器保證服務(wù)正常。停掉機器后要排查問題，思考分析步驟如下:

• 通過監(jiān)控發(fā)現(xiàn)只有一個key的ID調(diào)用發(fā)生下降（第一張），這臺機器上的其他key沒有任何問題，從數(shù)據(jù)庫更新號段正常。是不是數(shù)據(jù)庫死鎖了？
• 這個key在其他機器更新key是正常的，排除數(shù)據(jù)庫的問題，那么就是這臺機器的問題
• 查看log，發(fā)現(xiàn)這臺機器確實沒有更新數(shù)據(jù)庫，兩個號段的buffer都是空的。為什么更新數(shù)據(jù)庫失敗呢？難道是大量的超時？
• 仔細檢查log日志，發(fā)現(xiàn)并沒有超時的error。首先沒有超時，但是號段是null的，是不是線程的問題？難道是代碼邏輯有問題？
• 理了一遍邏輯發(fā)現(xiàn)代碼邏輯沒有問題，那是線程卡住了？
• 馬上抓幾次jstack log。果然發(fā)現(xiàn)有一條更新線程一直處于runable狀態(tài)（第二張），其他線程池里面的線程都是waiting狀態(tài)（禁用了服務(wù)，沒有請求不會更新).
• 確定是線程一直卡住了，先重啟這臺機器，保證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

不理解上面的排查步驟沒關(guān)系，理解成一句話就是:一個數(shù)據(jù)庫操作的線程一直處于runable狀態(tài)但是一直hand住沒有返回值

通過jstack的信息，可以發(fā)現(xiàn)是我們的一個事務(wù)在執(zhí)行conn,setAutoCommit(true)時，一直在native方法read…長時間read。我們有設(shè)置超時時間，但是為什么這里會沒有超時呢（發(fā)現(xiàn)時線程大概運行了有20min）？？？。咨詢DBA同事定位問題之后，大概得出是因為我們沒有設(shè)置socketTimeout。如果沒有設(shè)置socketTimeout將會依賴OS底層的timeout，線上大概是30min。雖然通過DBA同事的經(jīng)驗解決了問題，但是仍然存在疑問，為什么mysql存在兩種timeout機制呢？queryTimeout和socketTimeout？socketTimeout難道不應(yīng)該是queryTimeout的子集？queryTimeout應(yīng)該也能發(fā)現(xiàn)我們的Sql超時了??？

這就和JDBC的實現(xiàn)機制有關(guān)系了，為什么會有兩種Timeout機制的存在。用一種超時不能解決問題嗎？

JDBC執(zhí)行SQL的原理

這個名詞也就是queryTimeout，他是屬于應(yīng)用層面的timeout機制。用來控制我們sql語句執(zhí)行的時間的超時，但是mysql并沒有用他來發(fā)現(xiàn)所有的問題。下面摘抄一段Statement執(zhí)行SQL的代碼片段

CancelTask timeoutTask = null;//實現(xiàn)statementTimeout的timer。每一個SQL執(zhí)行都會創(chuàng)建一個

try {
    //有超時設(shè)置會初始化這個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();
    }
    //執(zhí)行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一個和現(xiàn)在相同的connection，然后執(zhí)行一條cancelStmt.execute(“KILL QUERY “ + CancelTask.this.connectionId); 語句給數(shù)據(jù)庫,讓數(shù)據(jù)庫立刻停止這個鏈接的SQL

那么整個SQL執(zhí)行的過程可以簡單的描述如下：

• 執(zhí)行SQL之前給每一個執(zhí)行SQL創(chuàng)建一個對應(yīng)超時時間的Timer，到了時間之后會去kill這調(diào)語句
• kill成功之后，數(shù)據(jù)庫會立即返回一個result，也就是上面代碼執(zhí)行SQL語句的返回值
• 正常執(zhí)行語句，拋出超時異常

這里值得注意的地方，為什么不直接用StatementTimeout直接發(fā)現(xiàn)超時，然后返回，不用管rs的結(jié)果到底是什么。為了防止超長時間的SQL在server端執(zhí)行，JDBC在發(fā)現(xiàn)自己的statement超時之后，會發(fā)一個kill指令給server，那么這個server指令有超時時間嗎？有timer嗎？在最開始我們代碼hang住的setAutoCommit（）指令有timer嗎？
沒有?。。?！

下面是通過jprofiler分別執(zhí)行statement和執(zhí)行setautoCommit兩個指令的內(nèi)存狀態(tài)圖，可以發(fā)現(xiàn)，后者是沒有timer對象的（第二張），而前者有(第一張)?。?！因為后者的代碼根本就沒有創(chuàng)建timer邏輯的部分?？梢栽谠创a里面看到后者會直接就調(diào)用底層的connectionImpl的execSQL方法執(zhí)行SQL

但是kill是通過copy鏈接來發(fā)送kill命令的。會有timer嗎?下圖是在發(fā)送kill指令時，用debug可以看到,kill 指令發(fā)送的時候statementTimeout是0，是不會創(chuàng)建TImer的 ，第一張圖是在執(zhí)行Statement SQL的，超時時間是我們設(shè)置的2s，第二張圖是執(zhí)行kill指令時的，可以發(fā)現(xiàn)超時時間是0，不會創(chuàng)建timer。仔細想想也能明白，如果kill指令也有timer，邏輯和statement sql一樣，那豈不是會無限循環(huán)??！

證明

第一種

socketTimeout設(shè)置得比StatementTimeOut小為1s，后者為5s執(zhí)行如下語句:

<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之后返回數(shù)據(jù)
select sleep(10) ,name from user where id=1

會在1s之后得到如下結(jié)果，看起來很正常，在timer沒有發(fā)起kill之前，因為socket沒有得到數(shù)據(jù)所以socket超時了，這一點提醒我們，設(shè)置socket超時一定要比statement長，不然你設(shè)置得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設(shè)置為2s，socketTime設(shè)置成6s。會在2s之后得到如下輸出。如果socketTime設(shè)置成比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的超時設(shè)置成5s，socket超時設(shè)置成15s。但是我會在發(fā)起kill之前把網(wǎng)絡(luò)給斷掉，來模擬出現(xiàn)網(wǎng)絡(luò)問題，或者server直接down掉的情況。會在15s后得到一下結(jié)果

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源碼部分有關(guān)系了。從上面的代碼可以看出，rs必須返回之后才會拋出異常，當rs不返回時不會繼續(xù)往下走的。rs什么時候返回？關(guān)于kill query什么時候返回，在網(wǎng)上找的一些資料 https://dev.mysql.com/doc/refman/5.7/en/kill.html

kill命令詳解

注：只針對innodb引擎

mysql KILL QUERY只abort線程當前提交執(zhí)行的操作，其他的保持不變，并且db server報SQL 語法異常（You have an error in your SQL syntax）。

根據(jù)當前被kill的statement是否在事務(wù)中，分兩種情況分析：

• (1) 不在事務(wù)中（未顯式開啟）
• innodb中statement具有原子性。因此kill掉后，會導(dǎo)致statement abort，回滾掉。
• (2) 在事務(wù)中
  • 假設(shè)事務(wù)中sql執(zhí)行順序是sql1;sql2;sql3; 在執(zhí)行sql2時被kill掉，則sql2會拋出異常，并且sql2執(zhí)行失敗。但是sql3依舊會執(zhí)行下去。此時如果在spring層做了事務(wù)回滾處理，會對三條sql全部回滾掉。
  • sql拋出的異常時MySQLSyntaxErrorException，我們會看到它是受檢異常，但是我們了解spring默認是只對非受檢異常做回滾處理的，怎么會這樣呢？是框架對其做了轉(zhuǎn)化，最終轉(zhuǎn)為非受檢異常，spring事物管理器就可以對其做回滾處理了。

mysql收到kill query后執(zhí)行時機

KILL操作后，該線程上會設(shè)置一個特殊的 kill標記位。通常需要一段時間后才能真正關(guān)閉線程，因為kill標記位只在特定的情況下才檢查。具體時機是

• 執(zhí)行SELECT查詢時，在ORDER BY或GROUP BY循環(huán)中，每次讀完一些行記錄塊后會檢查 kill標記位，如果發(fā)現(xiàn)存在，該語句會終止；
• 執(zhí)行ALTER TABLE時，在從原始表中每讀取一些行記錄塊后會檢查 kill 標記位，如果發(fā)現(xiàn)存在，該語句會終止，刪除臨時表；
• 執(zhí)行UPDATE和DELETE時，每讀取一些行記錄塊并且更新或刪除后會檢查 kill 標記位，如果發(fā)現(xiàn)存在，該語句會終止，回滾事務(wù)，若是在非事務(wù)表上的操作，則已發(fā)生變更的數(shù)據(jù)不會回滾；
• GET_LOCK() 函數(shù)返回NULL；
• INSERT DELAY線程會迅速內(nèi)存中的新增記錄，然后終止；
• 如果當前線程持有表級鎖，則會釋放，并終止；
• 如果線程的寫操作調(diào)用在等待釋放磁盤空間，則會直接拋出“磁盤空間滿”錯誤，然后終止；
• 當MyISAM表在執(zhí)行REPAIR TABLE 或 OPTIMIZE TABLE 時被 KILL的話，會導(dǎo)致該表損壞不可用，指導(dǎo)再次修復(fù)完成。
  

所以，當kill query這條指令發(fā)送過去的時候，由于網(wǎng)絡(luò)問題一直沒響應(yīng)，會等到socketTimeout之后，整個SQL語句的執(zhí)行才會返回。所以socketTimeout也不宜設(shè)置得太長，在網(wǎng)絡(luò)不好的時候超時時間基本上不會是statementTimeout的時長。這也就證明了jstack中的問題，那一時刻出現(xiàn)了網(wǎng)絡(luò)問題，到時setAutoCommit這條指令被卡住，由于沒有設(shè)置socket超時，得依賴os底層的socket超時時間30min，其實如果我們不重啟服務(wù)，相信30min鐘后服務(wù)會自愈。

最好大家自己執(zhí)行一下上面三種情況，就能很快理解

總結(jié)

• StatementTimeout主要是為了限制我們執(zhí)行SQL語句的時長，由于設(shè)計問題并不能包含所以超時情況
• 除了用戶自己寫的SQL，其他的SQL指令依賴的超時時間都是socket超時。例如執(zhí)行事務(wù)時的setAutoCommit和statement執(zhí)行SQL超時時執(zhí)行的kill query指令
• 可不可以只設(shè)置socket超時？最好不要，如果這樣的話會導(dǎo)致mysql server有大量長時間運行的SQL(沒有被超時kill)
• socketTimout一定要設(shè)置得大于statementTimeout，不然設(shè)置后者將會沒有任何意義
• 一個SQL就會有一個timer的產(chǎn)生，這一點以前是不知道的，以為都是依賴的底層超時

到此這篇關(guān)于JDBC超時機制的文章就介紹到這了,更多相關(guān)JDBC超時機制內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

資料

• 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
  

最新評論