一則線上MySql串連異常的排查過程，線上mysql排查

一則線上MySql串連異常的排查過程，線上mysql排查

Mysql作為一個常用資料庫，在互連網系統應用很多。有些故障是其自身的bug，有些則不是，這裡以前段時間遇到的問題舉例。

問題

當時遇到的癥狀是這樣的，我們的應用線上上測試環境，JMeter測試過程中，發現每次壓力測試開始時訪問低前幾個http request請求會逾時，而之後的請求持續測試中都不會。最後一點是Tomcat的log並沒有報什麼錯誤。

壓測的內容就是起200線程不停的向這個http頁面發送請求，這個頁面邏輯也比較簡單，會在後端向資料庫插入一條資料，串連池採用阿里的Druid（這個坑先留在這），tomcat中啟動並執行是常規web app應用，每個應用的JDBC串連池最大串連數只設了30，就是說就算4個tomcat一起連資料庫，最大也沒有多少串連。

嘗試排查

由於tomcat的log並沒有什麼錯，所以先開始嘗試重現錯誤。 錯誤重現開始並不容易，因為看起來比較隨機，後來經過總結，發現每次都是出現問題都是應用放了一晚上後，測試人員早上過來開始壓力測試時出現，開始懷疑跟閑置有關，所以後面的重現都按這個方式來，閑置半小時再開始嘗試重現。

找log

沒有log，就要看下JVM的stack資訊了。重現故障，上該機器上用jstack直接抓問題tomcat 的jvm資訊。

jps
列出機器的java進程號
jstack javaid
dump該java進程的stack資訊

拿到的stack資訊中發現了有用的東西：

“http-bio-8081-exec-4975” daemon prio=10 tid=0x00007f9d4c127000 nid=0x65db runnable [0x00007f9cc4544000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at **com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x0000000684d608c8> (a com.mysql.jdbc.util.ReadAheadInputStream)**
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3014)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3467)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3997)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.ConnectionImpl.pingInternal(ConnectionImpl.java:4092)
at com.mysql.jdbc.ConnectionImpl.ping(ConnectionImpl.java:4069)
at sun.reflect.GeneratedMethodAccessor94.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.alibaba.druid.pool.vendor.MySqlValidConnectionChecker.isValidConnection(MySqlValidConnectionChecker.java:98)
at com.alibaba.druid.pool.DruidAbstractDataSource.testConnectionInternal(DruidAbstractDataSource.java:1235)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:928)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:882)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:872)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:97)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:202)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:372)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy27.insert(Unknown Source)

可以看到HTTP請求從前端容器直到資料庫讀取時為止，卡在了資料庫讀取的地方，而且並不是JDBC驅動代碼裡的問題，而且出在socket讀取的地方：

com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x0000000684d608c8> (a com.mysql.jdbc.util.ReadAheadInputStream)*

根據這個錯誤搜尋了下，唯一有價值的就是N年前mysql官網上報的一個bug，同樣的錯誤，但處理的辦法並不治本。如提到了將JDBC串連字串改為：

useReadAheadInput=false&useUnbufferedInput=false

這隻是讓socket不去預讀網路緩衝區，但實際上這個時候Mysql的串連已經斷開了，並不知道是web應用這裡斷的還是Mysql斷的。

尋找串連池逾時

由於根據log看起來是應用的用戶端在socket上讀不到東西，肯定是應用與mysql的tcp串連斷了，所以開始排查應用串連池設定與mysql的連線逾時設定。

應用串連池設定

name=”maxWait” value=”60000”
擷取串連最大等待60秒
name=”testWhileIdle” value=”true”
測試空閑串連
name=”minEvictableIdleTimeMillis” value=”300000”
name=”timeBetweenEvictionRunsMillis” value=”60000”
Destroy線程會檢測串連的間隔時間

應用端的串連池設定沒有主動斷掉的設定。

mysql連線逾時設定

show global variables like ‘%timeout%’

看到mysql維持串連的timeout時間為28800，即8小時，資料庫端不會斷掉這個串連。

至此，問題的排查進入死胡同，兩邊都不會主動中斷連線，為什麼用戶端在閑置幾分鐘後會被斷掉？

還有一個疑點是同樣的代碼，資料庫也沒什麼變動，在另一個純測試環境完全沒有這個問題。

尋找網路問題

現在問題的重點懷疑方向就是線上環境網路問題。於是找營運的同事查看了下資料庫機器上linux有沒有什麼異常的配置，結果是沒有。

期間也懷疑為什麼用了阿里druid的串連池，現在設成每分鐘檢測串連池裡的串連，還是會在拿到串連的時候有失效的串連。

解決

斷斷續續折騰了2天，抱著死馬當活馬醫去諮詢了其他部門的同事，結果那兄弟說是不是閑置後卡在socketRead上？然後問了應用與資料庫是不是在不同網段上，馬上建議找網路的人查一下防火牆對tcp長連線逾時的設定。

這時候基本上就肯定是防火牆設定的問題，排查後發現兩個網段間華為交換器的長連線逾時設了3分鐘，由於java應用的串連池是盡量長時間的維持串連（幾個小時，低於資料庫的最長8小時設定），而防火牆認為超過3分鐘的串連是有問題的，直接斷掉了，這時應用與mysql都不知道tcp串連已經被斷了。

此次故障還暴露了阿里Druid開源串連池對串連處理邏輯的問題，串連池並沒有用單獨的線程去檢測所有串連有沒有斷開，查代碼後發現其只是在拿到串連時測試連接是否有效，處理邏輯沒有老牌c3p0嚴謹，之後將應用串連池實現更換為c3p0。

文章來自平台「麥芽麵包」。轉載請註明。