Mysql作為一個常用數(shù)據(jù)庫，在互聯(lián)網(wǎng)系統(tǒng)應(yīng)用很多。有些故障是其自身的bug，有些則不是，這里以前段時間遇到的問題舉例。

問題##

當(dāng)時遇到的癥狀是這樣的，我們的應(yīng)用在線上測試環(huán)境，JMeter測試過程中，發(fā)現(xiàn)每次壓力測試開始時訪問低前幾個http request請求會超時，而之后的請求持續(xù)測試中都不會。最后一點是Tomcat的log并沒有報什么錯誤。

壓測的內(nèi)容就是起200線程不停的向這個http頁面發(fā)送請求，這個頁面邏輯也比較簡單，會在后端向數(shù)據(jù)庫插入一條數(shù)據(jù)，連接池采用阿里的Druid(這個坑先留在這)，tomcat中運(yùn)行的是常規(guī)web app應(yīng)用，每個應(yīng)用的JDBC連接池最大連接數(shù)只設(shè)了30，就是說就算4個tomcat一起連數(shù)據(jù)庫，最大也沒有多少連接。

嘗試排查##

由于tomcat的log并沒有什么錯，所以先開始嘗試重現(xiàn)錯誤。 錯誤重現(xiàn)開始并不容易，因為看起來比較隨機(jī)，后來經(jīng)過總結(jié)，發(fā)現(xiàn)每次都是出現(xiàn)問題都是應(yīng)用放了一晚上后，測試人員早上過來開始壓力測試時出現(xiàn)，開始懷疑跟閑置有關(guān)，所以后面的重現(xiàn)都按這個方式來，閑置半小時再開始嘗試重現(xiàn)。

找log###

沒有l(wèi)og，就要看下JVM的stack信息了。重現(xiàn)故障，上該機(jī)器上用jstack直接抓問題tomcat 的jvm信息。

jps

列出機(jī)器的java進(jìn)程號

jstack javaid

dump該java進(jìn)程的stack信息

拿到的stack信息中發(fā)現(xiàn)了有用的東西：

"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請求從前端容器直到數(shù)據(jù)庫讀取時為止，卡在了數(shù)據(jù)庫讀取的地方，而且并不是JDBC驅(qū)動代碼里的問題，而且出在socket讀取的地方：

com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)

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

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

useReadAheadInput=false&useUnbufferedInput=false

這只是讓socket不去預(yù)讀網(wǎng)絡(luò)緩沖區(qū)，但實際上這個時候Mysql的連接已經(jīng)斷開了，并不知道是web應(yīng)用這里斷的還是Mysql斷的。

查找連接池超時###

由于根據(jù)log看起來是應(yīng)用的客戶端在socket上讀不到東西，肯定是應(yīng)用與mysql的tcp連接斷了，所以開始排查應(yīng)用連接池設(shè)置與mysql的連接超時設(shè)置。

應(yīng)用連接池設(shè)置

name="maxWait" value="60000"

獲取連接最大等待60秒

name="testWhileIdle" value="true"

測試空閑連接

name="minEvictableIdleTimeMillis" value="300000"

name="timeBetweenEvictionRunsMillis" value="60000"

Destroy線程會檢測連接的間隔時間

應(yīng)用端的連接池設(shè)置沒有主動斷掉的設(shè)置。

mysql連接超時設(shè)置

show global variables like '%timeout%'

看到mysql維持連接的timeout時間為28800，即8小時，數(shù)據(jù)庫端不會斷掉這個連接。

至此，問題的排查進(jìn)入死胡同，兩邊都不會主動斷開連接，為什么客戶端在閑置幾分鐘后會被斷掉？

還有一個疑點是同樣的代碼，數(shù)據(jù)庫也沒什么變動，在另一個純測試環(huán)境完全沒有這個問題。

查找網(wǎng)絡(luò)問題###

現(xiàn)在問題的重點懷疑方向就是線上環(huán)境網(wǎng)絡(luò)問題。于是找運(yùn)維的同事查看了下數(shù)據(jù)庫機(jī)器上linux有沒有什么異常的配置，結(jié)果是沒有。

期間也懷疑為什么用了阿里druid的連接池，現(xiàn)在設(shè)成每分鐘檢測連接池里的連接，還是會在拿到連接的時候有失效的連接。

解決###

斷斷續(xù)續(xù)折騰了2天，抱著死馬當(dāng)活馬醫(yī)去咨詢了其他部門的同事，結(jié)果那兄弟說是不是閑置后卡在socketRead上？然后問了應(yīng)用與數(shù)據(jù)庫是不是在不同網(wǎng)段上，馬上建議找網(wǎng)絡(luò)的人查一下防火墻對tcp長連接超時的設(shè)置。

這時候基本上就肯定是防火墻設(shè)置的問題，排查后發(fā)現(xiàn)兩個網(wǎng)段間華為交換機(jī)的長連接超時設(shè)了3分鐘，由于java應(yīng)用的連接池是盡量長時間的維持連接(幾個小時，低于數(shù)據(jù)庫的最長8小時設(shè)置)，而防火墻認(rèn)為超過3分鐘的連接是有問題的，直接斷掉了，這時應(yīng)用與mysql都不知道tcp連接已經(jīng)被斷了。

此次故障還暴露了阿里Druid開源連接池對連接處理邏輯的問題，連接池并沒有用單獨(dú)的線程去檢測所有連接有沒有斷開，查代碼后發(fā)現(xiàn)其只是在拿到連接時測試連接是否有效，處理邏輯沒有老牌c3p0嚴(yán)謹(jǐn)，之后將應(yīng)用連接池實現(xiàn)更換為c3p0。

文章來自微信平臺「麥芽面包」。轉(zhuǎn)載請注明。

總結(jié)

以上是生活随笔為你收集整理的mysql在线检测失败_一则线上MySql连接异常的排查过程的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。