詳解MySQL連接掛死的原因

更新時間：2021年05月18日 14:21:55 作者：華為云開發(fā)者社區(qū)

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

一、背景

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

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

架構(gòu)

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

mybatis，實(shí)現(xiàn) SQL <-> Method 的映射

hikaricp，實(shí)現(xiàn)數(shù)據(jù)庫連接池

mariadb-java-client，實(shí)現(xiàn) JDBC 驅(qū)動

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

說明

MySQL 部署兩臺實(shí)例，設(shè)定為互為主備的關(guān)系。
為每臺 MySQL 實(shí)例部署一個 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)換的，在同一時刻，VIP 只會指向其中的一個虛擬機(jī)（master）。當(dāng)主節(jié)點(diǎn)發(fā)生故障時，其他的 keepalived 會檢測到問題并重新選舉出新的 master，此后 VIP 將切換到另一個可用的 MySQL 實(shí)例節(jié)點(diǎn)上。這樣一來，MySQL 數(shù)據(jù)庫就擁有了基礎(chǔ)的高可用能力。

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

問題現(xiàn)象

本次的測試用例也是基于虛擬機(jī)故障的場景來設(shè)計的：

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

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

二、分析過程

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

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

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

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

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

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

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

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

連接池

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

從日志上看，在產(chǎn)生故障的時刻，業(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ù)操作獲取連接超時了（超過了30秒）。那么，會不會是連接數(shù)不夠用呢？

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

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

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

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

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

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

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

public class HikariPool{

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

      try {
         //使用預(yù)設(shè)的30s 超時時間
         long timeout = hardTimeout;
         do {
            //進(jìn)入循環(huán)，在指定時間內(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)記清除或不滿足存活條件時，關(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);

         //超時了，拋出異常
         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() 方法展示了獲取連接的整個流程，其中 connectionBag 是用于存放連接對象的容器對象。如果從 connectionBag 獲得的連接不再滿足存活條件，那么會將其手動關(guān)閉，代碼如下：

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();
            }
         });
      }
   }

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

isMarkedEvicted() 的返回結(jié)果是 true，即標(biāo)記為清除，如果連接存活時間超出最大生存時間(maxLifeTime)，或者距離上一次使用超過了idleTimeout，會被定時任務(wù)標(biāo)記為清除狀態(tài)，清除狀態(tài)的連接在獲取的時候才真正 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í)行超時
            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ā)生異常時，將失敗信息記錄到上下文
         lastConnectionFailure.set(e);
         logger.warn("{} - Failed to validate connection {} ({}). Possibly consider using a shorter maxLifetime value.",
                     poolName, connection, e.getMessage());
         return false;
      }
   }

}

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

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;
}

這里的異常消息和我們在業(yè)務(wù)服務(wù)中看到的異常日志基本上是吻合的，即除了超時產(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)用獲得連接的代碼大致梳理了一遍，整個過程如下圖所示：

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

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

陷入焦灼

在代碼分析之余，開發(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)行測試，并同時將 hikariCP 的日志級別設(shè)置為 DEBUG。

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

1. 初始化數(shù)據(jù)源，此時連接池 min-idle 設(shè)置為 10；

2. 每隔50ms 執(zhí)行一次SQL操作，查詢當(dāng)前的元數(shù)據(jù)表；

3. 將 MySQL 服務(wù)停止一段時間，觀察業(yè)務(wù)表現(xiàn)；

4. 將 MySQL 服務(wù)重新啟動，觀察業(yè)務(wù)表現(xiàn)。

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

//初始化過程，建立10個連接

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重啟

//重啟后，自動創(chuàng)建連接成功

DEBUG -HikariPool$PoolEntryCreator.call -Added connection MariaDbConnection@42c5503e

DEBUG -HikariPool$PoolEntryCreator.call -Added connection MariaDbConnection@695a7435

//連接池狀態(tài)，重新建立10個連接

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 重新啟動，業(yè)務(wù)操作又能自動恢復(fù)成功了。根據(jù)這個結(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ā)起訪問。

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

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

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

推測可能原因有二：

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

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

那么，情況二的可能性就很大了。帶著這個思路，繼續(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這個線程一直處于 socketRead 的可執(zhí)行狀態(tài)。從命名上看該線程應(yīng)該是 HikariCP 連接池用于建立連接的任務(wù)線程，socket 讀操作則來自于 MariaDbConnection.newConnection() 這個方法，即 mariadb-java-client 驅(qū)動層建立 MySQL 連接的一個操作，其中 ReadInitialHandShakePacket 初始化則屬于 MySQL 建鏈協(xié)議中的一個環(huán)節(jié)。

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

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

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

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

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

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

經(jīng)過代碼走讀，我們再次梳理了 hikariCP 建立連接的一個流程，其中涉及到幾個模塊：

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

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

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

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

         //在指定時間內(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();
      }
   }

注意到，無論是有沒有可用連接，該方法都會觸發(fā)一個 listener.addBagItem() 方法，HikariPool 對該接口的實(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è)計，當(dāng)產(chǎn)生新連接需求時，會異步觸發(fā) PoolEntryCreator 任務(wù)進(jìn)行補(bǔ)充。其中 PoolEntryCreator. createPoolEntry() 會完成 MySQL 驅(qū)動連接建立的所有事情，而我們的情況則恰恰是MySQL 建鏈過程產(chǎn)生了永久性阻塞。因此無論后面怎么獲取連接，新來的建鏈任務(wù)都會一直排隊(duì)等待，這便導(dǎo)致了業(yè)務(wù)上一直沒有連接可用。

下面這個圖說明了 hikariCP 的建鏈過程：

好了，讓我們在回顧一下前面關(guān)于可靠性測試的場景：

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

三、解決方案

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

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

對于優(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ù)，如下：

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

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

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

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

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

四、小結(jié)

本次分享了一次關(guān)于 MySQL 連接掛死問題排查的心路歷程，由于環(huán)境搭建的工作量巨大，而且該問題復(fù)現(xiàn)存在偶然性，整個分析過程還是有些坎坷的（其中也踩了坑）。的確，我們很容易被一些表面的現(xiàn)象所迷惑，而覺得問題很難解決時，更容易帶著偏向性思維去處理問題。例如本例中曾一致認(rèn)為連接池出現(xiàn)了問題，但實(shí)際上卻是由于 MySQL JDBC 驅(qū)動（mariadb driver）的一個不嚴(yán)謹(jǐn)?shù)呐渲盟鶎?dǎo)致。

從原則上講，應(yīng)該避免一切可能導(dǎo)致資源掛死的行為。如果我們能在前期對代碼及相關(guān)配置做好充分的排查工作，相信 996 就會離我們越來越遠(yuǎn)。

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

您可能感興趣的文章: