一、背景

近期由測(cè)試反饋的問題有點(diǎn)多，其中關(guān)于系統(tǒng)可靠性測(cè)試提出的問題令人感到頭疼，一來這類問題有時(shí)候?qū)儆凇芭及l(fā)”現(xiàn)象，難以在環(huán)境上快速?gòu)?fù)現(xiàn)；二來則是可靠性問題的定位鏈條有時(shí)候變得很長(zhǎng)，極端情況下可能要從 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ù)庫(kù)連接池

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ù)庫(kù)訪問。

Keepalived 是基于 VRRP 協(xié)議實(shí)現(xiàn)了路由層轉(zhuǎn)換的，在同一時(shí)刻，VIP 只會(huì)指向其中的一個(gè)虛擬機(jī)（master）。當(dāng)主節(jié)點(diǎn)發(fā)生故障時(shí)，其他的 keepalived 會(huì)檢測(cè)到問題并重新選舉出新的 master，此后 VIP 將切換到另一個(gè)可用的 MySQL 實(shí)例節(jié)點(diǎn)上。這樣一來，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)作。

問題現(xiàn)象

本次的測(cè)試用例也是基于虛擬機(jī)故障的場(chǎng)景來設(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)過多次的測(cè)試后發(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 任何配置上的毛病。

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

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

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

但在本次測(cè)試場(chǎng)景中，MySQL 容器銷毀會(huì)導(dǎo)致 keepalived 的端口探測(cè)產(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í)行 telnet 測(cè)試，發(fā)現(xià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í)了（超過了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，也就是說，就算在沒有任何業(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)行探測(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è)過程如下圖所示：

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

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

陷入焦灼

在代碼分析之余，開發(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)行測(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)生的日志如下：

//初始化過程，建立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è)到無效連接

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 版本問題的設(shè)想也再次落空，研發(fā)同學(xué)再次陷入焦灼。

撥開云霧見光明

多方面求證無果之后，我們最終嘗試在業(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)出可用連接呢？

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

• 該連接被某個(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é)。

簡(jiǎn)而言之，上面的線程剛好處于建鏈的一個(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 ListObject> 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)于可靠性測(cè)試的場(chǎng)景：

首先，MySQL 主實(shí)例發(fā)生故障，而緊接著 hikariCP 則檢測(cè)到了壞的連接(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í)便陷入了長(zhǎng)時(shí)間的阻塞式 socketRead 操作。而建鏈請(qǐng)求任務(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 來避免長(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ù)，如下：

具體參考：https://mariadb.com/kb/en/about-mariadb-connector-j/

如描述所說的，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=60000connectTimeout=30000serverTimezone=UTC

此后對(duì) MySQL 可靠性場(chǎng)景進(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)致資源掛死的行為。如果我們能在前期對(duì)代碼及相關(guān)配置做好充分的排查工作，相信 996 就會(huì)離我們?cè)絹碓竭h(yuǎn)。

以上就是詳解MySQL連接掛死的原因的詳細(xì)內(nèi)容，更多關(guān)于MySQL連接掛死的原因的資料請(qǐng)關(guān)注腳本之家其它相關(guān)文章！