MySQL 連接掛死了!該如何排查?

大家好，我是小富~

一、背景

近期由測(cè)試反饋的問(wèn)題有點(diǎn)多，其中關(guān)于系統(tǒng)可靠性測(cè)試提出的問(wèn)題令人感到頭疼，一來(lái)這類問(wèn)題有時(shí)候?qū)儆凇芭及l(fā)”現(xiàn)象，難以在環(huán)境上快速?gòu)?fù)現(xiàn)；二來(lái)則是可靠性問(wèn)題的定位鏈條有時(shí)候變得很長(zhǎng)，極端情況下可能要從 A 服務(wù)追蹤到 Z 服務(wù)，或者是從應(yīng)用代碼追溯到硬件層面。

本次分享的是一次關(guān)于 MySQL 高可用問(wèn)題的定位過(guò)程，其中曲折頗多但問(wèn)題本身卻比較有些代表性，遂將其記錄以供參考。

架構(gòu)

首先，本系統(tǒng)以 MySQL 作為主要的數(shù)據(jù)存儲(chǔ)部件。整一個(gè)是典型的微服務(wù)架構(gòu)（SpringBoot + SpringCloud），持久層則采用了如下幾個(gè)組件：

• mybatis，實(shí)現(xiàn) SQL <-> Method 的映射
• hikaricp，實(shí)現(xiàn)數(shù)據(jù)庫(kù)連接池
• mariadb-java-client，實(shí)現(xiàn) JDBC 驅(qū)動(dòng)

在 MySQL 服務(wù)端部分，后端采用了雙主架構(gòu)，前端以 keepalived 結(jié)合浮動(dòng)IP（VIP）做一層高可用。如下：

說(shuō)明

• MySQL 部署兩臺(tái)實(shí)例，設(shè)定為互為主備的關(guān)系。

• 為每臺(tái) MySQL 實(shí)例部署一個(gè) keepalived 進(jìn)程，由 keepalived 提供 VIP 高可用的故障切換。

  實(shí)際上，keepalived 和 MySQL 都實(shí)現(xiàn)了容器化，而 VIP 端口則映射到 VM 上的 nodePort 服務(wù)端口上。

• 業(yè)務(wù)服務(wù)一律使用 VIP 進(jìn)行數(shù)據(jù)庫(kù)訪問(wèn)。

Keepalived 是基于 VRRP 協(xié)議實(shí)現(xiàn)了路由層轉(zhuǎn)換的，在同一時(shí)刻，VIP 只會(huì)指向其中的一個(gè)虛擬機(jī)（master）。

當(dāng)主節(jié)點(diǎn)發(fā)生故障時(shí)，其他的 keepalived 會(huì)檢測(cè)到問(wèn)題并重新選舉出新的 master，此后 VIP 將切換到另一個(gè)可用的 MySQL 實(shí)例節(jié)點(diǎn)上。

這樣一來(lái)，MySQL 數(shù)據(jù)庫(kù)就擁有了基礎(chǔ)的高可用能力。

另外一點(diǎn)，Keepalived 還會(huì)對(duì) MySQL 實(shí)例進(jìn)行定時(shí)的健康檢查，一旦發(fā)現(xiàn) MySQL 實(shí)例不可用會(huì)將自身進(jìn)程殺死，進(jìn)而再觸發(fā) VIP 的切換動(dòng)作。

問(wèn)題現(xiàn)象

本次的測(cè)試用例也是基于虛擬機(jī)故障的場(chǎng)景來(lái)設(shè)計(jì)的：

      
        持續(xù)以較小的壓力向業(yè)務(wù)服務(wù)發(fā)起訪問(wèn)，隨后將其中一臺(tái) MySQL 的容器實(shí)例(master)重啟。
按照原有的評(píng)估，業(yè)務(wù)可能會(huì)產(chǎn)生很小的抖動(dòng)，但其中斷時(shí)間應(yīng)該保持在秒級(jí)。

      
    

然而經(jīng)過(guò)多次的測(cè)試后發(fā)現(xiàn)，在重啟 MySQL 主節(jié)點(diǎn)容器之后，有一定的概率會(huì)出現(xiàn)業(yè)務(wù)卻再也無(wú)法訪問(wèn)的情況！

二、分析過(guò)程

在發(fā)生問(wèn)題之后，開發(fā)同學(xué)的第一反應(yīng)是 MySQL 的高可用機(jī)制出了問(wèn)題。由于此前曾經(jīng)出現(xiàn)過(guò)由于 keepalived 配置不當(dāng)導(dǎo)致 VIP 未能及時(shí)切換的問(wèn)題，因此對(duì)其已經(jīng)有所戒備。

先是經(jīng)過(guò)一通的排查，然后并沒有找到 keepalived 任何配置上的毛病。

然后在沒有辦法的情況下，重新測(cè)試了幾次，問(wèn)題又復(fù)現(xiàn)了。

緊接著，我們提出了幾個(gè)疑點(diǎn)：

1. Keepalived 會(huì)根據(jù) MySQL 實(shí)例的可達(dá)性進(jìn)行判斷，會(huì)不會(huì)是健康檢查出了問(wèn)題？

但在本次測(cè)試場(chǎng)景中，MySQL 容器銷毀會(huì)導(dǎo)致 keepalived 的端口探測(cè)產(chǎn)生失敗，這同樣會(huì)導(dǎo)致 keepalived 失效。如果 keepalived 也發(fā)生了中止，那么 VIP 應(yīng)該能自動(dòng)發(fā)生搶占。而通過(guò)對(duì)比兩臺(tái)虛擬機(jī)節(jié)點(diǎn)的信息后，發(fā)現(xiàn) VIP 的確發(fā)生了切換。

1. 業(yè)務(wù)進(jìn)程所在的容器是否發(fā)生了網(wǎng)絡(luò)不可達(dá)的問(wèn)題？

   嘗試進(jìn)入容器，對(duì)當(dāng)前發(fā)生切換后的浮動(dòng)IP、端口執(zhí)行 telnet 測(cè)試，發(fā)現(xiàn)仍然能訪問(wèn)成功。

連接池排查

在排查前面兩個(gè)疑點(diǎn)之后，我們只能將目光轉(zhuǎn)向了業(yè)務(wù)服務(wù)的DB客戶端上。

從日志上看，在產(chǎn)生故障的時(shí)刻，業(yè)務(wù)側(cè)的確出現(xiàn)了一些異常，如下：

      
        Unable?to?acquire?JDBC?Connection?[n/a]
java.sql.SQLTransientConnectionException:?HikariPool-1?-?Connection?is?not?available,?request?timed?out?after?30000ms.
?at?com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:669)?~[HikariCP-2.7.9.jar!/:?]
?at?com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183)?~[HikariCP-2.7.9.jar!/:?]?
?...

      
    

這里提示的是業(yè)務(wù)操作獲取連接超時(shí)了（超過(guò)了30秒）。那么，會(huì)不會(huì)是連接數(shù)不夠用呢？

業(yè)務(wù)接入采用的是 hikariCP 連接池，這也是市面上流行度很高的一款組件了。

我們隨即檢查了當(dāng)前的連接池配置，如下：

      
        //最小空閑連接數(shù)
spring.datasource.hikari.minimum-idle=10
//連接池最大大小
spring.datasource.hikari.maximum-pool-size=50
//連接最大空閑時(shí)長(zhǎng)
spring.datasource.hikari.idle-timeout=60000
//連接生命時(shí)長(zhǎng)
spring.datasource.hikari.max-lifetime=1800000
//獲取連接的超時(shí)時(shí)長(zhǎng)
spring.datasource.hikari.connection-timeout=30000

      
    

其中 注意到 hikari 連接池配置了 minimum-idle = 10，也就是說(shuō)，就算在沒有任何業(yè)務(wù)的情況下，連接池應(yīng)該保證有 10 個(gè)連接。更何況當(dāng)前的業(yè)務(wù)訪問(wèn)量極低，不應(yīng)該存在連接數(shù)不夠使用的情況。

除此之外，另外一種可能性則可能是出現(xiàn)了“僵尸連接”，也就是說(shuō)在重啟的過(guò)程中，連接池一直沒有釋放這些不可用的連接，最終造成沒有可用連接的結(jié)果。

開發(fā)同學(xué)對(duì)"僵尸鏈接"的說(shuō)法深信不疑，傾向性的認(rèn)為這很可能是來(lái)自于 HikariCP 組件的某個(gè) BUG..

于是開始走讀 HikariCP 的源碼，發(fā)現(xiàn)應(yīng)用層向連接池請(qǐng)求連接的一處代碼如下：

      
        public?class?HikariPool{

???//獲取連接對(duì)象入口
???public?Connection?getConnection(final?long?hardTimeout)?throws?SQLException
???{
??????suspendResumeLock.acquire();
??????final?long?startTime?=?currentTime();

??????try?{
??????//使用預(yù)設(shè)的30s?超時(shí)時(shí)間
?????????long?timeout?=?hardTimeout;
?????????do?{
??????//進(jìn)入循環(huán)，在指定時(shí)間內(nèi)獲取可用連接
???//從?connectionBag?中獲取連接
????????????PoolEntry?poolEntry?=?connectionBag.borrow(timeout,?MILLISECONDS);
????????????if?(poolEntry?==?null)?{
???????????????break;?//?We?timed?out...?break?and?throw?exception
????????????}

????????????final?long?now?=?currentTime();
???//連接對(duì)象被標(biāo)記清除或不滿足存活條件時(shí)，關(guān)閉該連接
????????????if?(poolEntry.isMarkedEvicted()?||?(elapsedMillis(poolEntry.lastAccessed,?now)?>?aliveBypassWindowMs?&&?!isConnectionAlive(poolEntry.connection)))?{
???????????????closeConnection(poolEntry,?poolEntry.isMarkedEvicted()???EVICTED_CONNECTION_MESSAGE?:?DEAD_CONNECTION_MESSAGE);
???????????????timeout?=?hardTimeout?-?elapsedMillis(startTime);
????????????}
???//成功獲得連接對(duì)象
????????????else?{
???????????????metricsTracker.recordBorrowStats(poolEntry,?startTime);
???????????????return?poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry),?now);
????????????}
?????????}?while?(timeout?>?0L);

???//超時(shí)了，拋出異常
?????????metricsTracker.recordBorrowTimeoutStats(startTime);
?????????throw?createTimeoutException(startTime);
??????}
??????catch?(InterruptedException?e)?{
?????????Thread.currentThread().interrupt();
?????????throw?new?SQLException(poolName?+?"?-?Interrupted?during?connection?acquisition",?e);
??????}
??????finally?{
?????????suspendResumeLock.release();
??????}
???}
}

      
    

getConnection() 方法展示了獲取連接的整個(gè)流程，其中 connectionBag 是用于存放連接對(duì)象的容器對(duì)象。如果從 connectionBag 獲得的連接不再滿足存活條件，那么會(huì)將其手動(dòng)關(guān)閉，代碼如下：

      
        ???void?closeConnection(final?PoolEntry?poolEntry,?final?String?closureReason)
???{
??????//移除連接對(duì)象
??????if?(connectionBag.remove(poolEntry))?{
?????????final?Connection?connection?=?poolEntry.close();
???//異步關(guān)閉連接
?????????closeConnectionExecutor.execute(()?->?{
????????????quietlyCloseConnection(connection,?closureReason);
???//由于可用連接變少，將觸發(fā)填充連接池的任務(wù)
????????????if?(poolState?==?POOL_NORMAL)?{
???????????????fillPool();
????????????}
?????????});
??????}
???}

      
    

注意到，只有當(dāng)連接滿足下面條件中的其中一個(gè)時(shí)，會(huì)被執(zhí)行 close。

• isMarkedEvicted() 的返回結(jié)果是 true，即標(biāo)記為清除

  如果連接存活時(shí)間超出最大生存時(shí)間(maxLifeTime)，或者距離上一次使用超過(guò)了idleTimeout，會(huì)被定時(shí)任務(wù)標(biāo)記為清除狀態(tài)，清除狀態(tài)的連接在獲取的時(shí)候才真正 close。

• 500ms 內(nèi)沒有被使用，且連接已經(jīng)不再存活，即 isConnectionAlive() 返回 false

由于我們把 idleTimeout 和 maxLifeTime 都設(shè)置得非常大，因此需重點(diǎn)檢查 isConnectionAlive 方法中的判斷，如下：

      
        public?class?PoolBase{

???//判斷連接是否存活
???boolean?isConnectionAlive(final?Connection?connection)
???{
??????try?{
?????????try?{
??????//設(shè)置?JDBC?連接的執(zhí)行超時(shí)
????????????setNetworkTimeout(connection,?validationTimeout);

????????????final?int?validationSeconds?=?(int)?Math.max(1000L,?validationTimeout)?/?1000;

???//如果沒有設(shè)置?TestQuery，使用?JDBC4?的校驗(yàn)接口
????????????if?(isUseJdbc4Validation)?{
???????????????return?connection.isValid(validationSeconds);
????????????}

???//使用?TestQuery（如?select?1）語(yǔ)句對(duì)連接進(jìn)行探測(cè)
????????????try?(Statement?statement?=?connection.createStatement())?{
???????????????if?(isNetworkTimeoutSupported?!=?TRUE)?{
??????????????????setQueryTimeout(statement,?validationSeconds);
???????????????}

???????????????statement.execute(config.getConnectionTestQuery());
????????????}
?????????}
?????????finally?{
????????????setNetworkTimeout(connection,?networkTimeout);

????????????if?(isIsolateInternalQueries?&&?!isAutoCommit)?{
???????????????connection.rollback();
????????????}
?????????}

?????????return?true;
??????}
??????catch?(Exception?e)?{
??????//發(fā)生異常時(shí)，將失敗信息記錄到上下文
?????????lastConnectionFailure.set(e);
?????????logger.warn("{}?-?Failed?to?validate?connection?{}?({}).?Possibly?consider?using?a?shorter?maxLifetime?value.",
?????????????????????poolName,?connection,?e.getMessage());
?????????return?false;
??????}
???}

}

      
    

我們看到，在PoolBase.isConnectionAlive 方法中對(duì)連接執(zhí)行了一系列的探測(cè)，如果發(fā)生異常還會(huì)將異常信息記錄到當(dāng)前的線程上下文中。隨后，在 HikariPool 拋出異常時(shí)會(huì)將最后一次檢測(cè)失敗的異常也一同收集，如下：

      
        private?SQLException?createTimeoutException(long?startTime)
{
???logPoolState("Timeout?failure?");
???metricsTracker.recordConnectionTimeout();

???String?sqlState?=?null;
???//獲取最后一次連接失敗的異常
???final?Throwable?originalException?=?getLastConnectionFailure();
???if?(originalException?instanceof?SQLException)?{
??????sqlState?=?((SQLException)?originalException).getSQLState();
???}
???//拋出異常
???final?SQLException?connectionException?=?new?SQLTransientConnectionException(poolName?+?"?-?Connection?is?not?available,?request?timed?out?after?"?+?elapsedMillis(startTime)?+?"ms.",?sqlState,?originalException);
???if?(originalException?instanceof?SQLException)?{
??????connectionException.setNextException((SQLException)?originalException);
???}

???return?connectionException;
}

      
    

這里的異常消息和我們?cè)跇I(yè)務(wù)服務(wù)中看到的異常日志基本上是吻合的，即除了超時(shí)產(chǎn)生的 "Connection is not available, request timed out after xxxms" 消息之外，日志中還伴隨輸出了校驗(yàn)失敗的信息：

      
        ?Caused?by:?java.sql.SQLException:?Connection.setNetworkTimeout?cannot?be?called?on?a?closed?connection
?at?org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getSqlException(ExceptionMapper.java:211)?~[mariadb-java-client-2.2.6.jar!/:?]
?at?org.mariadb.jdbc.MariaDbConnection.setNetworkTimeout(MariaDbConnection.java:1632)?~[mariadb-java-client-2.2.6.jar!/:?]
?at?com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:541)?~[HikariCP-2.7.9.jar!/:?]
?at?com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:162)?~[HikariCP-2.7.9.jar!/:?]
?at?com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:172)?~[HikariCP-2.7.9.jar!/:?]
?at?com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148)?~[HikariCP-2.7.9.jar!/:?]
?at?com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)?~[HikariCP-2.7.9.jar!/:?]

      
    

到這里，我們已經(jīng)將應(yīng)用獲得連接的代碼大致梳理了一遍，整個(gè)過(guò)程如下圖所示：

從執(zhí)行邏輯上看，連接池的處理并沒有問(wèn)題，相反其在許多細(xì)節(jié)上都考慮到位了。在對(duì)非存活連接執(zhí)行 close 時(shí)，同樣調(diào)用了 removeFromBag 動(dòng)作將其從連接池中移除，因此也不應(yīng)該存在僵尸連接對(duì)象的問(wèn)題。

那么，我們之前的推測(cè)應(yīng)該就是錯(cuò)誤的！

陷入焦灼

在代碼分析之余，開發(fā)同學(xué)也注意到當(dāng)前使用的 hikariCP 版本為 3.4.5，而環(huán)境上出問(wèn)題的業(yè)務(wù)服務(wù)卻是 2.7.9 版本，這仿佛預(yù)示著什么.. 讓我們?cè)俅渭僭O(shè) hikariCP 2.7.9 版本存在某種未知的 BUG，導(dǎo)致了問(wèn)題的產(chǎn)生。

為了進(jìn)一步分析連接池對(duì)于服務(wù)端故障的行為處理，我們嘗試在本地機(jī)器上進(jìn)行模擬，這一次使用了 hikariCP 2.7.9 版本進(jìn)行測(cè)試，并同時(shí)將 hikariCP 的日志級(jí)別設(shè)置為 DEBUG。

模擬場(chǎng)景中，會(huì)由 由本地應(yīng)用程序連接本機(jī)的 MySQL 數(shù)據(jù)庫(kù)進(jìn)行操作，步驟如下：

      
        1. 初始化數(shù)據(jù)源，此時(shí)連接池 min-idle 設(shè)置為 10；
2. 每隔50ms 執(zhí)行一次SQL操作，查詢當(dāng)前的元數(shù)據(jù)表；
3. 將 MySQL 服務(wù)停止一段時(shí)間，觀察業(yè)務(wù)表現(xiàn)；
4. 將 MySQL 服務(wù)重新啟動(dòng)，觀察業(yè)務(wù)表現(xiàn)。

      
    

最終產(chǎn)生的日志如下：

      
        //初始化過(guò)程，建立10個(gè)連接
DEBUG?-HikariPool.logPoolState?-?Pool?stats?(total=1,?active=1,?idle=0,?waiting=0)
DEBUG?-HikariPool$PoolEntryCreator.call-?Added?connection?MariaDbConnection@71ab7c09
DEBUG?-HikariPool$PoolEntryCreator.call-?Added?connection?MariaDbConnection@7f6c9c4c
DEBUG?-HikariPool$PoolEntryCreator.call-?Added?connection?MariaDbConnection@7b531779
...
DEBUG?-HikariPool.logPoolState-?After?adding?stats?(total=10,?active=1,?idle=9,?waiting=0)

//執(zhí)行業(yè)務(wù)操作，成功
execute?statement:?true
test?time?-------1
execute?statement:?true
test?time?-------2

...
//停止MySQL
...
//檢測(cè)到無(wú)效連接
WARN??-PoolBase.isConnectionAlive?-?Failed?to?validate?connection?MariaDbConnection@9225652?((conn=38652)?
Connection.setNetworkTimeout?cannot?be?called?on?a?closed?connection).?Possibly?consider?using?a?shorter?maxLifetime?value.
WARN??-PoolBase.isConnectionAlive?-?Failed?to?validate?connection?MariaDbConnection@71ab7c09?((conn=38653)?
Connection.setNetworkTimeout?cannot?be?called?on?a?closed?connection).?Possibly?consider?using?a?shorter?maxLifetime?value.
//釋放連接
DEBUG?-PoolBase.quietlyCloseConnection(PoolBase.java:134)?-?Closing?connection?MariaDbConnection@9225652:?(connection?is?dead)?
DEBUG?-PoolBase.quietlyCloseConnection(PoolBase.java:134)?-?Closing?connection?MariaDbConnection@71ab7c09:?(connection?is?dead)

//嘗試創(chuàng)建連接失敗
DEBUG?-HikariPool.createPoolEntry?-?Cannot?acquire?connection?from?data?source
java.sql.SQLNonTransientConnectionException:?Could?not?connect?to?address=(host=localhost)(port=3306)(type=master)?:?
Socket?fail?to?connect?to?host:localhost,?port:3306.?Connection?refused:?connect
Caused?by:?java.sql.SQLNonTransientConnectionException:?Socket?fail?to?connect?to?host:localhost,?port:3306.?Connection?refused:?connect
?at?internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:73)?~[mariadb-java-client-2.6.0.jar:?]
?...

//持續(xù)失敗..?直到MySQL重啟

//重啟后，自動(dòng)創(chuàng)建連接成功
DEBUG?-HikariPool$PoolEntryCreator.call?-Added?connection?MariaDbConnection@42c5503e
DEBUG?-HikariPool$PoolEntryCreator.call?-Added?connection?MariaDbConnection@695a7435
//連接池狀態(tài)，重新建立10個(gè)連接
DEBUG?-HikariPool.logPoolState(HikariPool.java:421)?-After?adding?stats?(total=10,?active=1,?idle=9,?waiting=0)
//執(zhí)行業(yè)務(wù)操作，成功（已經(jīng)自愈）
execute?statement:?true

      
    

從日志上看，hikariCP 還是能成功檢測(cè)到壞死的連接并將其踢出連接池，一旦 MySQL 重新啟動(dòng)，業(yè)務(wù)操作又能自動(dòng)恢復(fù)成功了。根據(jù)這個(gè)結(jié)果，基于 hikariCP 版本問(wèn)題的設(shè)想也再次落空，研發(fā)同學(xué)再次陷入焦灼。

撥開云霧見光明

多方面求證無(wú)果之后，我們最終嘗試在業(yè)務(wù)服務(wù)所在的容器內(nèi)進(jìn)行抓包，看是否能發(fā)現(xiàn)一些蛛絲馬跡。

進(jìn)入故障容器，執(zhí)行 tcpdump -i eth0 tcp port 30052 進(jìn)行抓包，然后對(duì)業(yè)務(wù)接口發(fā)起訪問(wèn)。

此時(shí)令人詭異的事情發(fā)生了，沒有任何網(wǎng)絡(luò)包產(chǎn)生！而業(yè)務(wù)日志在 30s 之后也出現(xiàn)了獲取連接失敗的異常。

我們通過(guò) netstat 命令檢查網(wǎng)絡(luò)連接，發(fā)現(xiàn)只有一個(gè) ESTABLISHED 狀態(tài)的 TCP 連接。

也就是說(shuō)，當(dāng)前業(yè)務(wù)實(shí)例和 MySQL 服務(wù)端是存在一個(gè)建好的連接的，但為什么業(yè)務(wù)還是報(bào)出可用連接呢？

推測(cè)可能原因有二：

• 該連接被某個(gè)業(yè)務(wù)（如定時(shí)器）一直占用。
• 該連接實(shí)際上還沒有辦法使用，可能處于某種僵死的狀態(tài)。

對(duì)于原因一，很快就可以被推翻，一來(lái)當(dāng)前服務(wù)并沒有什么定時(shí)器任務(wù)，二來(lái)就算該連接被占用，按照連接池的原理，只要沒有達(dá)到上限，新的業(yè)務(wù)請(qǐng)求應(yīng)該會(huì)促使連接池進(jìn)行新連接的建立，那么無(wú)論是從 netstat 命令檢查還是 tcpdump 的結(jié)果來(lái)看，不應(yīng)該一直是只有一個(gè)連接的狀況。

那么，情況二的可能性就很大了。帶著這個(gè)思路，繼續(xù)分析 Java 進(jìn)程的線程棧。

執(zhí)行 kill -3 pid 將線程棧輸出后分析，果不其然，在當(dāng)前 thread stack 中發(fā)現(xiàn)了如下的條目：

      
        "HikariPool-1?connection?adder"?#121?daemon?prio=5?os_prio=0?tid=0x00007f1300021800?nid=0xad?runnable?[0x00007f12d82e5000]
???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:171)
?at?java.net.SocketInputStream.read(SocketInputStream.java:141)
?at?java.io.FilterInputStream.read(FilterInputStream.java:133)
?at?org.mariadb.jdbc.internal.io.input.ReadAheadBufferedStream.fillBuffer(ReadAheadBufferedStream.java:129)
?at?org.mariadb.jdbc.internal.io.input.ReadAheadBufferedStream.read(ReadAheadBufferedStream.java:102)
?-?locked?<0x00000000d7f5b480>?(a?org.mariadb.jdbc.internal.io.input.ReadAheadBufferedStream)
?at?org.mariadb.jdbc.internal.io.input.StandardPacketInputStream.getPacketArray(StandardPacketInputStream.java:241)
?at?org.mariadb.jdbc.internal.io.input.StandardPacketInputStream.getPacket(StandardPacketInputStream.java:212)
?at?org.mariadb.jdbc.internal.com.read.ReadInitialHandShakePacket.<init>(ReadInitialHandShakePacket.java:90)
?at?org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol.createConnection(AbstractConnectProtocol.java:480)
?at?org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol.connectWithoutProxy(AbstractConnectProtocol.java:1236)
?at?org.mariadb.jdbc.internal.util.Utils.retrieveProxy(Utils.java:610)
?at?org.mariadb.jdbc.MariaDbConnection.newConnection(MariaDbConnection.java:142)
?at?org.mariadb.jdbc.Driver.connect(Driver.java:86)
?at?com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
?at?com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
?at?com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
?at?com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)

      
    

這里顯示 HikariPool-1 connection adder 這個(gè)線程一直處于 socketRead 的可執(zhí)行狀態(tài)。從命名上看該線程應(yīng)該是 HikariCP 連接池用于建立連接的任務(wù)線程，socket 讀操作則來(lái)自于 MariaDbConnection.newConnection() 這個(gè)方法，即 mariadb-java-client 驅(qū)動(dòng)層建立 MySQL 連接的一個(gè)操作，其中 ReadInitialHandShakePacket 初始化則屬于 MySQL 建鏈協(xié)議中的一個(gè)環(huán)節(jié)。

簡(jiǎn)而言之，上面的線程剛好處于建鏈的一個(gè)過(guò)程態(tài)，關(guān)于 mariadb 驅(qū)動(dòng)和 MySQL 建鏈的過(guò)程大致如下：

MySQL 建鏈?zhǔn)紫仁墙?TCP 連接（三次握手），客戶端會(huì)讀取 MySQL 協(xié)議的一個(gè)初始化握手消息包，內(nèi)部包含 MySQL 版本號(hào)，鑒權(quán)算法等等信息，之后再進(jìn)入身份鑒權(quán)的環(huán)節(jié)。

這里的問(wèn)題就在于 ReadInitialHandShakePacket 初始化（讀取握手消息包）一直處于 socket read 的一個(gè)狀態(tài)。

如果此時(shí) MySQL 遠(yuǎn)端主機(jī)故障了，那么該操作就會(huì)一直卡住。而此時(shí)的連接雖然已經(jīng)建立（處于 ESTABLISHED 狀態(tài)），但卻一直沒能完成協(xié)議握手和后面的身份鑒權(quán)流程，即該連接只能算一個(gè)半成品（無(wú)法進(jìn)入 hikariCP 連接池的列表中）。從故障服務(wù)的 DEBUG 日志也可以看到，連接池持續(xù)是沒有可用連接的，如下：

      
        DEBUG?HikariPool.logPoolState?-->?Before?cleanup?stats?(total=0,?active=0,?idle=0,?waiting=3)

      
    

另一個(gè)需要解釋的問(wèn)題則是，這樣一個(gè) socket read 操作的阻塞是否就造成了整個(gè)連接池的阻塞呢？

經(jīng)過(guò)代碼走讀，我們?cè)俅问崂砹?hikariCP 建立連接的一個(gè)流程，其中涉及到幾個(gè)模塊：

• HikariPool，連接池實(shí)例，由該對(duì)象連接的獲取、釋放以及連接的維護(hù)。
• ConnectionBag，連接對(duì)象容器，存放當(dāng)前的連接對(duì)象列表，用于提供可用連接。
• AddConnectionExecutor，添加連接的執(zhí)行器，命名如 "HikariPool-1 connection adder"，是一個(gè)單線程的線程池。
• PoolEntryCreator，添加連接的任務(wù)，實(shí)現(xiàn)創(chuàng)建連接的具體邏輯。
• HouseKeeper，內(nèi)部定時(shí)器，用于實(shí)現(xiàn)連接的超時(shí)淘汰、連接池的補(bǔ)充等工作。

HouseKeeper 在連接池初始化后的 100ms 觸發(fā)執(zhí)行，其調(diào)用 fillPool() 方法完成連接池的填充，例如 min-idle 是10，那么初始化就會(huì)創(chuàng)建10個(gè)連接。ConnectionBag 維護(hù)了當(dāng)前連接對(duì)象的列表，該模塊還維護(hù)了請(qǐng)求連接者(waiters)的一個(gè)計(jì)數(shù)器，用于評(píng)估當(dāng)前連接數(shù)的需求。

其中，borrow 方法的邏輯如下：

      
        ?public?T?borrow(long?timeout,?final?TimeUnit?timeUnit)?throws?InterruptedException
???{
??????//?嘗試從?thread-local?中獲取
??????final?List<Object>?list?=?threadList.get();
??????for?(int?i?=?list.size()?-?1;?i?>=?0;?i--)?{
?????????...
??????}

??????//?計(jì)算當(dāng)前等待請(qǐng)求的任務(wù)
??????final?int?waiting?=?waiters.incrementAndGet();
??????try?{
?????????for?(T?bagEntry?:?sharedList)?{
????????????if?(bagEntry.compareAndSet(STATE_NOT_IN_USE,?STATE_IN_USE))?{
???????????????//如果獲得了可用連接，會(huì)觸發(fā)填充任務(wù)
???????????????if?(waiting?>?1)?{
??????????????????listener.addBagItem(waiting?-?1);
???????????????}
???????????????return?bagEntry;
????????????}
?????????}

???//沒有可用連接，先觸發(fā)填充任務(wù)
?????????listener.addBagItem(waiting);

???//在指定時(shí)間內(nèi)等待可用連接進(jìn)入
?????????timeout?=?timeUnit.toNanos(timeout);
?????????do?{
????????????final?long?start?=?currentTime();
????????????final?T?bagEntry?=?handoffQueue.poll(timeout,?NANOSECONDS);
????????????if?(bagEntry?==?null?||?bagEntry.compareAndSet(STATE_NOT_IN_USE,?STATE_IN_USE))?{
???????????????return?bagEntry;
????????????}

????????????timeout?-=?elapsedNanos(start);
?????????}?while?(timeout?>?10_000);

?????????return?null;
??????}
??????finally?{
?????????waiters.decrementAndGet();
??????}
???}

      
    

注意到，無(wú)論是有沒有可用連接，該方法都會(huì)觸發(fā)一個(gè) listener.addBagItem() 方法，HikariPool 對(duì)該接口的實(shí)現(xiàn)如下：

      
        ???public?void?addBagItem(final?int?waiting)
???{
??????final?boolean?shouldAdd?=?waiting?-?addConnectionQueueReadOnlyView.size()?>=?0;?//?Yes,?>=?is?intentional.
??????if?(shouldAdd)?{
?????????//調(diào)用?AddConnectionExecutor?提交創(chuàng)建連接的任務(wù)
?????????addConnectionExecutor.submit(poolEntryCreator);
??????}
??????else?{
?????????logger.debug("{}?-?Add?connection?elided,?waiting?{},?queue?{}",?poolName,?waiting,?addConnectionQueueReadOnlyView.size());
??????}
???}

      
    

PoolEntryCreator 則實(shí)現(xiàn)了創(chuàng)建連接的具體邏輯，如下：

      
        public?class?PoolEntryCreator{
?????@Override
??????public?Boolean?call()
??????{
?????????long?sleepBackoff?=?250L;
???//判斷是否需要建立連接
?????????while?(poolState?==?POOL_NORMAL?&&?shouldCreateAnotherConnection())?{
??????//創(chuàng)建?MySQL?連接
????????????final?PoolEntry?poolEntry?=?createPoolEntry();
???
????????????if?(poolEntry?!=?null)?{
??????//建立連接成功，直接返回。
???????????????connectionBag.add(poolEntry);
???????????????logger.debug("{}?-?Added?connection?{}",?poolName,?poolEntry.connection);
???????????????if?(loggingPrefix?!=?null)?{
??????????????????logPoolState(loggingPrefix);
???????????????}
???????????????return?Boolean.TRUE;
????????????}
????????????...
?????????}

?????????//?Pool?is?suspended?or?shutdown?or?at?max?size
?????????return?Boolean.FALSE;
??????}
}?

      
    

由此可見，AddConnectionExecutor 采用了單線程的設(shè)計(jì)，當(dāng)產(chǎn)生新連接需求時(shí)，會(huì)異步觸發(fā) PoolEntryCreator 任務(wù)進(jìn)行補(bǔ)充。其中 PoolEntryCreator. createPoolEntry() 會(huì)完成 MySQL 驅(qū)動(dòng)連接建立的所有事情，而我們的情況則恰恰是 MySQL 建鏈過(guò)程產(chǎn)生了永久性阻塞。因此無(wú)論后面怎么獲取連接，新來(lái)的建鏈任務(wù)都會(huì)一直排隊(duì)等待，這便導(dǎo)致了業(yè)務(wù)上一直沒有連接可用。

下面這個(gè)圖說(shuō)明了 hikariCP 的建鏈過(guò)程：

好了，讓我們?cè)诨仡櫼幌虑懊骊P(guān)于可靠性測(cè)試的場(chǎng)景：

首先，MySQL 主實(shí)例發(fā)生故障，而緊接著 hikariCP 則檢測(cè)到了壞的連接(connection is dead)并將其釋放，在釋放關(guān)閉連接的同時(shí)又發(fā)現(xiàn)連接數(shù)需要補(bǔ)充，進(jìn)而立即觸發(fā)了新的建鏈請(qǐng)求。而問(wèn)題就剛好出在這一次建鏈請(qǐng)求上，TCP 握手的部分是成功了（客戶端和 MySQL VM 上 nodePort 的完成連接），但在接下來(lái)由于當(dāng)前的 MySQL 容器已經(jīng)停止（此時(shí) VIP 也切換到了另一臺(tái) MySQL 實(shí)例上），因此客戶端再也無(wú)法獲得原 MySQL 實(shí)例的握手包響應(yīng)（該握手屬于MySQL應(yīng)用層的協(xié)議），此時(shí)便陷入了長(zhǎng)時(shí)間的阻塞式 socketRead 操作。而建鏈請(qǐng)求任務(wù)恰恰好采用了單線程運(yùn)作，進(jìn)一步則導(dǎo)致了所有業(yè)務(wù)的阻塞。

三、解決方案

在了解了事情的來(lái)龍去脈之后，我們主要考慮從兩方面進(jìn)行優(yōu)化：

• 優(yōu)化一，增加 HirakiPool 中 AddConnectionExecutor 線程的數(shù)量，這樣即使第一個(gè)線程出現(xiàn)掛死，還有其他的線程能參與建鏈任務(wù)的分配。
• 優(yōu)化二，出問(wèn)題的 socketRead 是一種同步阻塞式的調(diào)用，可通過(guò) SO_TIMEOUT 來(lái)避免長(zhǎng)時(shí)間掛死。

對(duì)于優(yōu)化點(diǎn)一，我們一致認(rèn)為用處并不大，如果連接出現(xiàn)了掛死那么相當(dāng)于線程資源已經(jīng)泄露，對(duì)服務(wù)后續(xù)的穩(wěn)定運(yùn)行十分不利，而且 hikariCP 在這里也已經(jīng)將其寫死了。因此關(guān)鍵的方案還是避免阻塞式的調(diào)用。

查閱了 mariadb-java-client 官方文檔后，發(fā)現(xiàn)可以在 JDBC URL 中指定網(wǎng)絡(luò)IO 的超時(shí)參數(shù)，如下：

Parameter	Description
socketTimeout	Defined the network socket timeout (SO_TIMEOUT) in milliseconds. Value of 0 disables this timeout.Default: 0 (standard configuration) or 10000ms (using "aurora" failover configuration). since 1.1.7

如描述所說(shuō)的，socketTimeout 可以設(shè)置 socket 的 SO_TIMEOUT 屬性，從而達(dá)到控制超時(shí)時(shí)間的目的。默認(rèn)是 0，即不超時(shí)。

我們?cè)?MySQL JDBC URL 中加入了相關(guān)的參數(shù)，如下：

      
        spring.datasource.url=jdbc:mysql://10.0.71.13:33052/appdb?socketTimeout=60000&connectTimeout=30000&serverTimezone=UTC

      
    

此后對(duì) MySQL 可靠性場(chǎng)景進(jìn)行多次驗(yàn)證，發(fā)現(xiàn)連接掛死的現(xiàn)象已經(jīng)不再出現(xiàn)，此時(shí)問(wèn)題得到解決。

四、小結(jié)

本次分享了一次關(guān)于 MySQL 連接掛死問(wèn)題排查的心路歷程，由于環(huán)境搭建的工作量巨大，而且該問(wèn)題復(fù)現(xiàn)存在偶然性，整個(gè)分析過(guò)程還是有些坎坷的（其中也踩了坑）。

的確，我們很容易被一些表面的現(xiàn)象所迷惑，而覺得問(wèn)題很難解決時(shí)，更容易帶著偏向性思維去處理問(wèn)題。

例如本例中曾一致認(rèn)為連接池出現(xiàn)了問(wèn)題，但實(shí)際上卻是由于 MySQL JDBC 驅(qū)動(dòng)（mariadb driver）的一個(gè)不嚴(yán)謹(jǐn)?shù)呐渲盟鶎?dǎo)致。

從原則上講，應(yīng)該避免一切可能導(dǎo)致資源掛死的行為。

··········? END? ··············

在看 、 點(diǎn)贊 、 轉(zhuǎn)發(fā) ，是對(duì)我最大的鼓勵(lì) 。

技術(shù)書籍公眾號(hào)內(nèi)回復(fù)[? pdf ?] Get 。

面試筆記、springcloud進(jìn)階實(shí)戰(zhàn)PDF，公眾號(hào)內(nèi)回復(fù)[? 1222 ?]?Get。

有幾個(gè) 技術(shù)群 ，想進(jìn)的同學(xué)可以加我好友，備注： 進(jìn)群 ，一起成長(zhǎng)。