摘要: 本次分享的是一次關(guān)于 MySQL 高可用問題的定位過程,其中曲折頗多但問題本身卻比較有些代表性英岭,遂將其記錄以供參考湾盒。
一、背景
近期由測試反饋的問題有點(diǎn)多诅妹,其中關(guān)于系統(tǒng)可靠性測試提出的問題令人感到頭疼罚勾,一來這類問題有時(shí)候?qū)儆凇芭及l(fā)”現(xiàn)象毅人,難以在環(huán)境上快速復(fù)現(xiàn);二來則是可靠性問題的定位鏈條有時(shí)候變得很長尖殃,極端情況下可能要從 A 服務(wù)追蹤到 Z 服務(wù)丈莺,或者是從應(yīng)用代碼追溯到硬件層面。
本次分享的是一次關(guān)于 MySQL 高可用問題的定位過程分衫,其中曲折頗多但問題本身卻比較有些代表性场刑,遂將其記錄以供參考。
架構(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ì)對 MySQL 實(shí)例進(jìn)行定時(shí)的健康檢查,一旦發(fā)現(xiàn) MySQL 實(shí)例不可用會(huì)將自身進(jìn)程殺死耻台,進(jìn)而再觸發(fā) VIP 的切換動(dòng)作空免。
問題現(xiàn)象
本次的測試用例也是基于虛擬機(jī)故障的場景來設(shè)計(jì)的:
<pre class="prettyprint hljs less" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">持續(xù)以較小的壓力向業(yè)務(wù)服務(wù)發(fā)起訪問,隨后將其中一臺(tái) MySQL 的容器實(shí)例(master)重啟盆耽。
按照原有的評估蹋砚,業(yè)務(wù)可能會(huì)產(chǎn)生很小的抖動(dòng)扼菠,但其中斷時(shí)間應(yīng)該保持在秒級。</pre>
然而經(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í)切換的問題泽篮,因此對其已經(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ā)生搶占。而通過對比兩臺(tái)虛擬機(jī)節(jié)點(diǎn)的信息后味咳,發(fā)現(xiàn) VIP 的確發(fā)生了切換庇勃。
2. 業(yè)務(wù)進(jìn)程所在的容器是否發(fā)生了網(wǎng)絡(luò)不可達(dá)的問題檬嘀?
嘗試進(jìn)入容器槽驶,對當(dāng)前發(fā)生切換后的浮動(dòng)IP、端口執(zhí)行 telnet 測試鸳兽,發(fā)現(xiàn)仍然能訪問成功掂铐。
連接池
在排查前面兩個(gè)疑點(diǎn)之后,我們只能將目光轉(zhuǎn)向了業(yè)務(wù)服務(wù)的DB客戶端上揍异。
從日志上看全陨,在產(chǎn)生故障的時(shí)刻,業(yè)務(wù)側(cè)的確出現(xiàn)了一些異常衷掷,如下:
<pre class="prettyprint hljs css" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">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!/:?]
... </pre>
這里提示的是業(yè)務(wù)操作獲取連接超時(shí)了(超過了30秒)辱姨。那么,會(huì)不會(huì)是連接數(shù)不夠用呢戚嗅?
業(yè)務(wù)接入采用的是 hikariCP 連接池雨涛,這也是市面上流行度很高的一款組件了枢舶。
我們隨即檢查了當(dāng)前的連接池配置,如下:
<pre class="prettyprint hljs swift" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">//最小空閑連接數(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 </pre>
其中 注意到 hikari 連接池配置了 minimum-idle = 10替久,也就是說凉泄,就算在沒有任何業(yè)務(wù)的情況下,連接池應(yīng)該保證有 10 個(gè)連接蚯根。更何況當(dāng)前的業(yè)務(wù)訪問量極低后众,不應(yīng)該存在連接數(shù)不夠使用的情況。
除此之外颅拦,另外一種可能性則可能是出現(xiàn)了“僵尸連接”蒂誉,也就是說在重啟的過程中,連接池一直沒有釋放這些不可用的連接矩距,最終造成沒有可用連接的結(jié)果拗盒。
開發(fā)同學(xué)對"僵尸鏈接"的說法深信不疑,傾向性的認(rèn)為這很可能是來自于 HikariCP 組件的某個(gè) BUG…
于是開始走讀 HikariCP 的源碼锥债,發(fā)現(xiàn)應(yīng)用層向連接池請求連接的一處代碼如下:
<pre class="prettyprint hljs java" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">public class HikariPool{
//獲取連接對象入口
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();
//連接對象被標(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);
}
//成功獲得連接對象
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();
}
}
} </pre>
getConnection() 方法展示了獲取連接的整個(gè)流程登夫,其中 connectionBag 是用于存放連接對象的容器對象。如果從 connectionBag 獲得的連接不再滿足存活條件允趟,那么會(huì)將其手動(dòng)關(guān)閉恼策,代碼如下:
<pre class="prettyprint hljs dart" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;"> void closeConnection(final PoolEntry poolEntry, final String closureReason)
{
//移除連接對象
if (connectionBag.remove(poolEntry)) {
final Connection connection = poolEntry.close();
//異步關(guān)閉連接
closeConnectionExecutor.execute(() -> {
quietlyCloseConnection(connection, closureReason);
//由于可用連接變少,將觸發(fā)填充連接池的任務(wù)
if (poolState == POOL_NORMAL) {
fillPool();
}
});
}
} </pre>
注意到潮剪,只有當(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 方法中的判斷,如下:
<pre class="prettyprint hljs kotlin" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">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)語句對連接進(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;
}
}
} </pre>
我們看到,在PoolBase.isConnectionAlive 方法中對連接執(zhí)行了一系列的探測怖辆,如果發(fā)生異常還會(huì)將異常信息記錄到當(dāng)前的線程上下文中是复。隨后沉填,在 HikariPool 拋出異常時(shí)會(huì)將最后一次檢測失敗的異常也一同收集,如下:
<pre class="prettyprint hljs java" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">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;
} </pre>
這里的異常消息和我們在業(yè)務(wù)服務(wù)中看到的異常日志基本上是吻合的佑笋,即除了超時(shí)產(chǎn)生的 “Connection is not available, request timed out after xxxms” 消息之外翼闹,日志中還伴隨輸出了校驗(yàn)失敗的信息:
<pre class="prettyprint hljs css" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">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!/:?] </pre>
到這里,我們已經(jīng)將應(yīng)用獲得連接的代碼大致梳理了一遍蒋纬,整個(gè)過程如下圖所示:
從執(zhí)行邏輯上看猎荠,連接池的處理并沒有問題,相反其在許多細(xì)節(jié)上都考慮到位了蜀备。在對非存活連接執(zhí)行 close 時(shí)关摇,同樣調(diào)用了 removeFromBag 動(dòng)作將其從連接池中移除,因此也不應(yīng)該存在僵尸連接對象的問題碾阁。
那么输虱,我們之前的推測應(yīng)該就是錯(cuò)誤的!
陷入焦灼
在代碼分析之余脂凶,開發(fā)同學(xué)也注意到當(dāng)前使用的 hikariCP 版本為 3.4.5宪睹,而環(huán)境上出問題的業(yè)務(wù)服務(wù)卻是 2.7.9 版本,這仿佛預(yù)示著什么… 讓我們再次假設(shè) hikariCP 2.7.9 版本存在某種未知的 BUG蚕钦,導(dǎo)致了問題的產(chǎn)生亭病。
為了進(jìn)一步分析連接池對于服務(wù)端故障的行為處理,我們嘗試在本地機(jī)器上進(jìn)行模擬嘶居,這一次使用了 hikariCP 2.7.9 版本進(jìn)行測試罪帖,并同時(shí)將 hikariCP 的日志級別設(shè)置為 DEBUG。
模擬場景中邮屁,會(huì)由 由本地應(yīng)用程序連接本機(jī)的 MySQL 數(shù)據(jù)庫進(jìn)行操作整袁,步驟如下:
<pre class="prettyprint hljs markdown" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">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)盗飒。</pre>
最終產(chǎn)生的日志如下:
<pre class="prettyprint hljs sql" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">//初始化過程,建立10個(gè)連接
DEBUG -HikariPool.logPoolState - Pool stats (total=1, active=1, idle=0, waiting=0)
DEBUG -HikariPoolPoolEntryCreator.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 -HikariPoolPoolEntryCreator.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 </pre>
從日志上看宣渗,hikariCP 還是能成功檢測到壞死的連接并將其踢出連接池抖所,一旦 MySQL 重新啟動(dòng),業(yè)務(wù)操作又能自動(dòng)恢復(fù)成功了痕囱。根據(jù)這個(gè)結(jié)果田轧,基于 hikariCP 版本問題的設(shè)想也再次落空,研發(fā)同學(xué)再次陷入焦灼鞍恢。
撥開云霧見光明
多方面求證無果之后傻粘,我們最終嘗試在業(yè)務(wù)服務(wù)所在的容器內(nèi)進(jìn)行抓包,看是否能發(fā)現(xiàn)一些蛛絲馬跡帮掉。
進(jìn)入故障容器弦悉,執(zhí)行 **tcpdump -i eth0 tcp port 30052 **進(jìn)行抓包,然后對業(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)。
對于原因一痛黎,很快就可以被推翻予弧,一來當(dāng)前服務(wù)并沒有什么定時(shí)器任務(wù),二來就算該連接被占用湖饱,按照連接池的原理掖蛤,只要沒有達(dá)到上限,新的業(yè)務(wù)請求應(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)了如下的條目:
<pre class="prettyprint hljs vim" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">"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) </pre>
這里顯示 ** 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 版本號肠槽,鑒權(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ù)是沒有可用連接的,如下:
<pre class="prettyprint hljs lua" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">DEBUG HikariPool.logPoolState --> Before cleanup stats (total=0, active=0, idle=0, waiting=3) </pre>
另一個(gè)需要解釋的問題則是柬姚,這樣一個(gè) socket read 操作的阻塞是否就造成了整個(gè)連接池的阻塞呢拟杉?
經(jīng)過代碼走讀,我們再次梳理了 hikariCP 建立連接的一個(gè)流程量承,其中涉及到幾個(gè)模塊:
- HikariPool搬设,連接池實(shí)例,由該對象連接的獲取撕捍、釋放以及連接的維護(hù)拿穴。
- ConnectionBag,連接對象容器忧风,存放當(dāng)前的連接對象列表默色,用于提供可用連接。
- 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)前連接對象的列表税灌,該模塊還維護(hù)了請求連接者(waiters)的一個(gè)計(jì)數(shù)器均函,用于評估當(dāng)前連接數(shù)的需求。
其中菱涤,borrow 方法的邏輯如下:
<pre class="prettyprint hljs gradle" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;"> 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)前等待請求的任務(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();
}
} </pre>
注意到粘秆,無論是有沒有可用連接如迟,該方法都會(huì)觸發(fā)一個(gè) listener.addBagItem() 方法,HikariPool 對該接口的實(shí)現(xiàn)如下:
<pre class="prettyprint hljs gradle" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">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;
}
} </pre>
由此可見昔搂,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 的建鏈過程:
好了别凹,讓我們在回顧一下前面關(guān)于可靠性測試的場景:
首先草讶,MySQL 主實(shí)例發(fā)生故障,而緊接著 hikariCP 則檢測到了壞的連接(connection is dead)并將其釋放炉菲,在釋放關(guān)閉連接的同時(shí)又發(fā)現(xiàn)連接數(shù)需要補(bǔ)充堕战,進(jìn)而立即觸發(fā)了新的建鏈請求。
而問題就剛好出在這一次建鏈請求上拍霜,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 操作越驻。而建鏈請求任務(wù)恰恰好采用了單線程運(yùn)作,進(jìn)一步則導(dǎo)致了所有業(yè)務(wù)的阻塞。
三缀旁、解決方案
在了解了事情的來龍去脈之后记劈,我們主要考慮從兩方面進(jìn)行優(yōu)化:
- 優(yōu)化一,增加 HirakiPool 中 AddConnectionExecutor 線程的數(shù)量并巍,這樣即使第一個(gè)線程出現(xiàn)掛死目木,還有其他的線程能參與建鏈任務(wù)的分配。
- 優(yōu)化二懊渡,出問題的 socketRead 是一種同步阻塞式的調(diào)用刽射,可通過 SO_TIMEOUT 來避免長時(shí)間掛死。
對于優(yōu)化點(diǎn)一剃执,我們一致認(rèn)為用處并不大誓禁,如果連接出現(xiàn)了掛死那么相當(dāng)于線程資源已經(jīng)泄露,對服務(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ù)戒祠,如下:
具體參考: https://mariadb.com/kb/en/about-mariadb-connector-j/
如描述所說的,socketTimeout 可以設(shè)置 socket 的 SO_TIMEOUT 屬性速种,從而達(dá)到控制超時(shí)時(shí)間的目的姜盈。默認(rèn)是 0,即不超時(shí)配阵。
我們在 MySQL JDBC URL 中加入了相關(guān)的參數(shù)馏颂,如下:
<pre class="prettyprint hljs groovy" style="color: rgb(0, 0, 0); font-family: "Courier New"; font-size: 12px; margin: 5px 8px; padding: 5px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">spring.datasource.url=jdbc:mysql://10.0.71.13:33052/appdb?socketTimeout=60000&connectTimeout=30000&serverTimezone=UTC </pre>
此后對 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)致資源掛死的行為纳寂。如果我們能在前期對代碼及相關(guān)配置做好充分的排查工作,相信 996 就會(huì)離我們越來越遠(yuǎn)泻拦。
本文分享自華為云社區(qū)《MySQL 連接為什么掛死了毙芜?》,原文作者:TANG卓章 聪轿。
相關(guān)推薦
看完三件事??
========
如果你覺得這篇內(nèi)容對你還蠻有幫助猾浦,我想邀請你幫我三個(gè)小忙:
點(diǎn)贊陆错,轉(zhuǎn)發(fā),有你們的 『點(diǎn)贊和評論』金赦,才是我創(chuàng)造的動(dòng)力音瓷。
關(guān)注公眾號 『 Java斗帝 』,不定期分享原創(chuàng)知識(shí)夹抗。
同時(shí)可以期待后續(xù)文章ing??