本次分享了一次關(guān)于 MySQL 連接掛死問題排查的心路歷程，由于環(huán)境搭建的工作量巨大，而且該問題復(fù)現(xiàn)存在偶然性，整個(gè)分析過程還是有些坎坷的（其中也踩了坑）。
一、背景
近期由測試反饋的問題有點(diǎn)多，其中關(guān)于系統(tǒng)可靠性測試提出的問題令人感到頭疼，一來這類問題有時(shí)候?qū)儆?ldquo;偶發(fā)”現(xiàn)象，難以在環(huán)境上快速復(fù)現(xiàn)；二來則是可靠性問題的定位鏈條有時(shí)候變得很長，極端情況下可能要從 A 服務(wù)追蹤到 Z 服務(wù)，或者是從應(yīng)用代碼追溯到硬件層面。
本次分享的是一次關(guān)于 MySQL 高可用問題的定位過程，其中曲折頗多但問題本身卻比較有些代表性，遂將其記錄以供參考。
1、架構(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ù)庫連接池
- mariadb-JAVA-client，實(shí)現(xiàn) JDBC 驅(qū)動(dòng)
在 MySQL 服務(wù)端部分，后端采用了雙主架構(gòu)，前端以 keepalived 結(jié)合浮動(dòng)IP（VIP）做一層高可用。如下：
- 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ù)庫訪問。
Keepalived 是基于 VRRP 協(xié)議實(shí)現(xiàn)了路由層轉(zhuǎn)換的，在同一時(shí)刻，VIP 只會(huì)指向其中的一個(gè)虛擬機(jī)（master）。
當(dāng)主節(jié)點(diǎn)發(fā)生故障時(shí)，其他的 keepalived 會(huì)檢測到問題并重新選舉出新的 master，此后 VIP 將切換到另一個(gè)可用的 MySQL 實(shí)例節(jié)點(diǎn)上。
這樣一來，MySQL 數(shù)據(jù)庫就擁有了基礎(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)作。
2、問題現(xiàn)象
本次的測試用例也是基于虛擬機(jī)故障的場景來設(shè)計(jì)的：
持續(xù)以較小的壓力向業(yè)務(wù)服務(wù)發(fā)起訪問，隨后將其中一臺(tái) MySQL 的容器實(shí)例(master)重啟。
按照原有的評(píng)估，業(yè)務(wù)可能會(huì)產(chǎn)生很小的抖動(dòng)，但其中斷時(shí)間應(yīng)該保持在秒級(jí)。
然而經(jīng)過多次的測試后發(fā)現(xiàn)，在重啟 MySQL 主節(jié)點(diǎn)容器之后，有一定的概率會(huì)出現(xiàn)業(yè)務(wù)卻再也無法訪問的情況！
二、分析過程
在發(fā)生問題之后，開發(fā)同學(xué)的第一反應(yīng)是 MySQL 的高可用機(jī)制出了問題。由于此前曾經(jīng)出現(xiàn)過由于 keepalived 配置不當(dāng)導(dǎo)致 VIP 未能及時(shí)切換的問題，因此對(duì)其已經(jīng)有所戒備。
先是經(jīng)過一通的排查，然后并沒有找到 keepalived 任何配置上的毛病。
然后在沒有辦法的情況下，重新測試了幾次，問題又復(fù)現(xiàn)了。
緊接著，我們提出了幾個(gè)疑點(diǎn)：
1）Keepalived 會(huì)根據(jù) MySQL 實(shí)例的可達(dá)性進(jìn)行判斷，會(huì)不會(huì)是健康檢查出了問題？
但在本次測試場景中，MySQL 容器銷毀會(huì)導(dǎo)致 keepalived 的端口探測產(chǎn)生失敗，這同樣會(huì)導(dǎo)致 keepalived 失效。如果 keepalived 也發(fā)生了中止，那么 VIP 應(yīng)該能自動(dòng)發(fā)生搶占。而通過對(duì)比兩臺(tái)虛擬機(jī)節(jié)點(diǎn)的信息后，發(fā)現(xiàn) VIP 的確發(fā)生了切換。
2）業(yè)務(wù)進(jìn)程所在的容器是否發(fā)生了網(wǎng)絡(luò)不可達(dá)的問題？
嘗試進(jìn)入容器，對(duì)當(dāng)前發(fā)生切換后的浮動(dòng)IP、端口執(zhí)行 te.NET 測試，發(fā)現(xiàn)仍然能訪問成功。
1、連接池排查
在排查前面兩個(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í)了（超過了30秒）。那么，會(huì)不會(huì)是連接數(shù)不夠用呢？
業(yè)務(wù)接入采用的是 hikariCP 連接池，這也是市面上流行度很高的一款組件了。
我們隨即檢查了當(dāng)前的連接池配置，如下：
//最小空閑連接數(shù)
spring.datasource.hikari.minimum-idle=10
//連接池最大大小
spring.datasource.hikari.maximum-pool-size=50
//連接最大空閑時(shí)長
spring.datasource.hikari.idle-timeout=60000
//連接生命時(shí)長
spring.datasource.hikari.max-lifetime=1800000
//獲取連接的超時(shí)時(shí)長
spring.datasource.hikari.connection-timeout=30000
其中 注意到 hikari 連接池配置了 minimum-idle = 10，也就是說，就算在沒有任何業(yè)務(wù)的情況下，連接池應(yīng)該保證有 10 個(gè)連接。更何況當(dāng)前的業(yè)務(wù)訪問量極低，不應(yīng)該存在連接數(shù)不夠使用的情況。
除此之外，另外一種可能性則可能是出現(xiàn)了“僵尸連接”，也就是說在重啟的過程中，連接池一直沒有釋放這些不可用的連接，最終造成沒有可用連接的結(jié)果。
開發(fā)同學(xué)對(duì)"僵尸鏈接"的說法深信不疑，傾向性的認(rèn)為這很可能是來自于 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)，或者距離上一次使用超過了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）語句對(duì)連接進(jìn)行探測
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í)行了一系列的探測，如果發(fā)生異常還會(huì)將異常信息記錄到當(dāng)前的線程上下文中。隨后，在 HikariPool 拋出異常時(shí)會(huì)將最后一次檢測失敗的異常也一同收集，如下：
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è)過程如下圖所示：
從執(zhí)行邏輯上看，連接池的處理并沒有問題，相反其在許多細(xì)節(jié)上都考慮到位了。在對(duì)非存活連接執(zhí)行 close 時(shí)，同樣調(diào)用了 removeFromBag 動(dòng)作將其從連接池中移除，因此也不應(yīng)該存在僵尸連接對(duì)象的問題。
那么，我們之前的推測應(yīng)該就是錯(cuò)誤的！
2、陷入焦灼
在代碼分析之余，開發(fā)同學(xué)也注意到當(dāng)前使用的 hikariCP 版本為 3.4.5，而環(huán)境上出問題的業(yè)務(wù)服務(wù)卻是 2.7.9 版本，這仿佛預(yù)示著什么.. 讓我們?cè)俅渭僭O(shè) hikariCP 2.7.9 版本存在某種未知的 BUG，導(dǎo)致了問題的產(chǎn)生。
為了進(jìn)一步分析連接池對(duì)于服務(wù)端故障的行為處理，我們嘗試在本地機(jī)器上進(jìn)行模擬，這一次使用了 hikariCP 2.7.9 版本進(jìn)行測試，并同時(shí)將 hikariCP 的日志級(jí)別設(shè)置為 DEBUG。
模擬場景中，會(huì)由 由本地應(yīng)用程序連接本機(jī)的 MySQL 數(shù)據(jù)庫進(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)生的日志如下：
//初始化過程，建立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
...
//檢測到無效連接
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 還是能成功檢測到壞死的連接并將其踢出連接池，一旦 MySQL 重新啟動(dòng)，業(yè)務(wù)操作又能自動(dòng)恢復(fù)成功了。根據(jù)這個(gè)結(jié)果，基于 hikariCP 版本問題的設(shè)想也再次落空，研發(fā)同學(xué)再次陷入焦灼。
3、撥開云霧見光明
多方面求證無果之后，我們最終嘗試在業(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ā)起訪問。
此時(shí)令人詭異的事情發(fā)生了，沒有任何網(wǎng)絡(luò)包產(chǎn)生！而業(yè)務(wù)日志在 30s 之后也出現(xiàn)了獲取連接失敗的異常。
我們通過 netstat 命令檢查網(wǎng)絡(luò)連接，發(fā)現(xiàn)只有一個(gè) ESTABLISHED 狀態(tài)的 TCP 連接。
也就是說，當(dāng)前業(yè)務(wù)實(shí)例和 MySQL 服務(wù)端是存在一個(gè)建好的連接的，但為什么業(yè)務(wù)還是報(bào)出可用連接呢？
推測可能原因有二：
- 該連接被某個(gè)業(yè)務(wù)（如定時(shí)器）一直占用。
- 該連接實(shí)際上還沒有辦法使用，可能處于某種僵死的狀態(tài)。
對(duì)于原因一，很快就可以被推翻，一來當(dāng)前服務(wù)并沒有什么定時(shí)器任務(wù)，二來就算該連接被占用，按照連接池的原理，只要沒有達(dá)到上限，新的業(yè)務(wù)請(qǐng)求應(yīng)該會(huì)促使連接池進(jìn)行新連接的建立，那么無論是從 netstat 命令檢查還是 tcpdump 的結(jié)果來看，不應(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 讀操作則來自于 MariaDbConnection.newConnection() 這個(gè)方法，即 mariadb-java-client 驅(qū)動(dòng)層建立 MySQL 連接的一個(gè)操作，其中 ReadInitialHandShakePacket 初始化則屬于 MySQL 建鏈協(xié)議中的一個(gè)環(huán)節(jié)。
簡而言之，上面的線程剛好處于建鏈的一個(gè)過程態(tài)，關(guān)于 mariadb 驅(qū)動(dòng)和 MySQL 建鏈的過程大致如下：
MySQL 建鏈?zhǔn)紫仁墙?TCP 連接（三次握手），客戶端會(huì)讀取 MySQL 協(xié)議的一個(gè)初始化握手消息包，內(nèi)部包含 MySQL 版本號(hào)，鑒權(quán)算法等等信息，之后再進(jìn)入身份鑒權(quán)的環(huán)節(jié)。
這里的問題就在于 ReadInitialHandShakePacket 初始化（讀取握手消息包）一直處于 socket read 的一個(gè)狀態(tài)。
如果此時(shí) MySQL 遠(yuǎn)端主機(jī)故障了，那么該操作就會(huì)一直卡住。而此時(shí)的連接雖然已經(jīng)建立（處于 ESTABLISHED 狀態(tài)），但卻一直沒能完成協(xié)議握手和后面的身份鑒權(quán)流程，即該連接只能算一個(gè)半成品（無法進(jìn)入 hikariCP 連接池的列表中）。從故障服務(wù)的 DEBUG 日志也可以看到，連接池持續(xù)是沒有可用連接的，如下：
DEBUG HikariPool.logPoolState --> Before cleanup stats (total=0, active=0, idle=0, waiting=3)
另一個(gè)需要解釋的問題則是，這樣一個(gè) socket read 操作的阻塞是否就造成了整個(gè)連接池的阻塞呢？
經(jīng)過代碼走讀，我們?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();
}
}
注意到，無論是有沒有可用連接，該方法都會(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 建鏈過程產(chǎn)生了永久性阻塞。因此無論后面怎么獲取連接，新來的建鏈任務(wù)都會(huì)一直排隊(duì)等待，這便導(dǎo)致了業(yè)務(wù)上一直沒有連接可用。
下面這個(gè)圖說明了 hikariCP 的建鏈過程：
好了，讓我們?cè)诨仡櫼幌虑懊骊P(guān)于可靠性測試的場景：
首先，MySQL 主實(shí)例發(fā)生故障，而緊接著 hikariCP 則檢測到了壞的連接(connection is dead)并將其釋放，在釋放關(guān)閉連接的同時(shí)又發(fā)現(xiàn)連接數(shù)需要補(bǔ)充，進(jìn)而立即觸發(fā)了新的建鏈請(qǐng)求。而問題就剛好出在這一次建鏈請(qǐng)求上，TCP 握手的部分是成功了（客戶端和 MySQL VM 上 nodePort 的完成連接），但在接下來由于當(dāng)前的 MySQL 容器已經(jīng)停止（此時(shí) VIP 也切換到了另一臺(tái) MySQL 實(shí)例上），因此客戶端再也無法獲得原 MySQL 實(shí)例的握手包響應(yīng)（該握手屬于MySQL應(yīng)用層的協(xié)議），此時(shí)便陷入了長時(shí)間的阻塞式 socketRead 操作。而建鏈請(qǐng)求任務(wù)恰恰好采用了單線程運(yùn)作，進(jìn)一步則導(dǎo)致了所有業(yè)務(wù)的阻塞。
三、解決方案
在了解了事情的來龍去脈之后，我們主要考慮從兩方面進(jìn)行優(yōu)化：
1）優(yōu)化一，增加 HirakiPool 中 AddConnectionExecutor 線程的數(shù)量，這樣即使第一個(gè)線程出現(xiàn)掛死，還有其他的線程能參與建鏈任務(wù)的分配。
2）優(yōu)化二，出問題的 socketRead 是一種同步阻塞式的調(diào)用，可通過 SO_TIMEOUT 來避免長時(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ù)，如下：
如描述所說的，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&cnotallow=30000&serverTimeznotallow=UTC
此后對(duì) MySQL 可靠性場景進(jìn)行多次驗(yàn)證，發(fā)現(xiàn)連接掛死的現(xiàn)象已經(jīng)不再出現(xiàn)，此時(shí)問題得到解決。
四、小結(jié)
本次分享了一次關(guān)于 MySQL 連接掛死問題排查的心路歷程，由于環(huán)境搭建的工作量巨大，而且該問題復(fù)現(xiàn)存在偶然性，整個(gè)分析過程還是有些坎坷的（其中也踩了坑）。
的確，我們很容易被一些表面的現(xiàn)象所迷惑，而覺得問題很難解決時(shí)，更容易帶著偏向性思維去處理問題。
例如本例中曾一致認(rèn)為連接池出現(xiàn)了問題，但實(shí)際上卻是由于 MySQL JDBC 驅(qū)動(dòng)（mariadb driver）的一個(gè)不嚴(yán)謹(jǐn)?shù)呐渲盟鶎?dǎo)致。
從原則上講，應(yīng)該避免一切可能導(dǎo)致資源掛死的行為。
