前言

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

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

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

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

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

JDBC執(zhí)行SQL的原理

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

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

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

那么整個(gè)SQL執(zhí)行的過(guò)程可以簡(jiǎn)單的描述如下：

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

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

下面是通過(guò)jprofiler分別執(zhí)行statement和執(zhí)行setautoCommit兩個(gè)指令的內(nèi)存狀態(tài)圖，可以發(fā)現(xiàn)，后者是沒(méi)有timer對(duì)象的（第二張），而前者有(第一張)?。?！因?yàn)楹笳叩拇a根本就沒(méi)有創(chuàng)建timer邏輯的部分。可以在源碼里面看到后者會(huì)直接就調(diào)用底層的connectionImpl的execSQL方法執(zhí)行SQL

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

證明

第一種

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

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

會(huì)在1s之后得到如下結(jié)果，看起來(lái)很正常，在timer沒(méi)有發(fā)起kill之前，因?yàn)閟ocket沒(méi)有得到數(shù)據(jù)所以socket超時(shí)了，這一點(diǎn)提醒我們，設(shè)置socket超時(shí)一定要比statement長(zhǎng)，不然你設(shè)置得statement超時(shí)將毫無(wú)意義

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。會(huì)在2s之后得到如下輸出。如果socketTime設(shè)置成比statement大，那么在后者超時(shí)之后，會(huì)去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í)設(shè)置成5s，socket超時(shí)設(shè)置成15s。但是我會(huì)在發(fā)起kill之前把網(wǎng)絡(luò)給斷掉，來(lái)模擬出現(xiàn)網(wǎng)絡(luò)問(wèn)題，或者server直接down掉的情況。會(huì)在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的超時(shí)的時(shí)間呢？這就和上面JDBC源碼部分有關(guān)系了。從上面的代碼可以看出，rs必須返回之后才會(huì)拋出異常，當(dāng)rs不返回時(shí)不會(huì)繼續(xù)往下走的。rs什么時(shí)候返回？關(guān)于kill query什么時(shí)候返回，在網(wǎng)上找的一些資料 https://dev.mysql.com/doc/refman/5.7/en/kill.html

kill命令詳解

注：只針對(duì)innodb引擎

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

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

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

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

KILL操作后，該線程上會(huì)設(shè)置一個(gè)特殊的 kill標(biāo)記位。通常需要一段時(shí)間后才能真正關(guān)閉線程，因?yàn)閗ill標(biāo)記位只在特定的情況下才檢查。具體時(shí)機(jī)是

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

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

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

總結(jié)

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

到此這篇關(guān)于JDBC超時(shí)機(jī)制的文章就介紹到這了,更多相關(guān)JDBC超時(shí)機(jī)制內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(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
  

最新評(píng)論