一、背景

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

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

1、架構

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

【資料圖】

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

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

MySQL 部署兩臺實例，設定為互為主備的關系。為每臺 MySQL 實例部署一個 keepalived 進程，由 keepalived 提供 VIP 高可用的故障切換。實際上，keepalived 和 MySQL 都實現(xiàn)了容器化，而 VIP 端口則映射到 VM 上的 nodePort 服務端口上。業(yè)務服務一律使用 VIP 進行數(shù)據(jù)庫訪問。

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

當主節(jié)點發(fā)生故障時，其他的 keepalived 會檢測到問題并重新選舉出新的 master，此后 VIP 將切換到另一個可用的 MySQL 實例節(jié)點上。

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

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

2、問題現(xiàn)象

本次的測試用例也是基于虛擬機故障的場景來設計的：

持續(xù)以較小的壓力向業(yè)務服務發(fā)起訪問，隨后將其中一臺 MySQL 的容器實例(master)重啟。

按照原有的評估，業(yè)務可能會產(chǎn)生很小的抖動，但其中斷時間應該保持在秒級。

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

二、分析過程

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

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

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

緊接著，我們提出了幾個疑點：

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

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

2）業(yè)務進程所在的容器是否發(fā)生了網(wǎng)絡不可達的問題？

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

1、連接池排查

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

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

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

我們隨即檢查了當前的連接池配置，如下：

//最小空閑連接數(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è)務的情況下，連接池應該保證有 10 個連接。更何況當前的業(yè)務訪問量極低，不應該存在連接數(shù)不夠使用的情況。

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

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

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

public class HikariPool{   //獲取連接對象入口   public Connection getConnection(final long hardTimeout) throws SQLException{      suspendResumeLock.acquire();      final long startTime = currentTime();      try {      //使用預設的30s 超時時間         long timeout = hardTimeout;         do {      //進入循環(huán)，在指定時間內獲取可用連接   //從 connectionBag 中獲取連接            PoolEntry poolEntry = connectionBag.borrow(timeout, MILLISECONDS);            if (poolEntry == null) {               break; // We timed out... break and throw exception            }            final long now = currentTime();   //連接對象被標記清除或不滿足存活條件時，關閉該連接            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 獲得的連接不再滿足存活條件，那么會將其手動關閉，代碼如下：

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

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

isMarkedEvicted() 的返回結果是 true，即標記為清除

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

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

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

public class PoolBase{   //判斷連接是否存活   boolean isConnectionAlive(final Connection connection){      try {         try {      //設置 JDBC 連接的執(zhí)行超時            setNetworkTimeout(connection, validationTimeout);            final int validationSeconds = (int) Math.max(1000L, validationTimeout) / 1000;   //如果沒有設置 TestQuery，使用 JDBC4 的校驗接口            if (isUseJdbc4Validation) {               return connection.isValid(validationSeconds);            }   //使用 TestQuery（如 select 1）語句對連接進行探測            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ā)生異常還會將異常信息記錄到當前的線程上下文中。隨后，在 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è)務服務中看到的異常日志基本上是吻合的，即除了超時產(chǎn)生的 "Connection is not available, request timed out after xxxms" 消息之外，日志中還伴隨輸出了校驗失敗的信息：

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)將應用獲得連接的代碼大致梳理了一遍，整個過程如下圖所示：

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

那么，我們之前的推測應該就是錯誤的！

2、陷入焦灼

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

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

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

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

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

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

4）將 MySQL 服務重新啟動，觀察業(yè)務表現(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@71ab7c09DEBUG -HikariPool$PoolEntryCreator.call- Added connection MariaDbConnection@7f6c9c4cDEBUG -HikariPool$PoolEntryCreator.call- Added connection MariaDbConnection@7b531779...DEBUG -HikariPool.logPoolState- After adding stats (total=10, active=1, idle=9, waiting=0)//執(zhí)行業(yè)務操作，成功execute statement: truetest time -------1execute statement: truetest 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 sourcejava.sql.SQLNonTransientConnectionException: Could not connect to address=(host=localhost)(port=3306)(type=master) : Socket fail to connect to host:localhost, port:3306. Connection refused: connectCaused 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@42c5503eDEBUG -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è)務操作，成功（已經(jīng)自愈）execute statement: true

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

3、撥開云霧見光明

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

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

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

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

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

推測可能原因有二：

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

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

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

執(zhí)行 kill -3 pid 將線程棧輸出后分析，果不其然，在當前 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.(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)。從命名上看該線程應該是 HikariCP 連接池用于建立連接的任務線程，socket 讀操作則來自于 MariaDbConnection.newConnection() 這個方法，即 mariadb-java-client 驅動層建立 MySQL 連接的一個操作，其中 ReadInitialHandShakePacket 初始化則屬于 MySQL 建鏈協(xié)議中的一個環(huán)節(jié)。

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

MySQL 建鏈首先是建立 TCP 連接（三次握手），客戶端會讀取 MySQL 協(xié)議的一個初始化握手消息包，內部包含 MySQL 版本號，鑒權算法等等信息，之后再進入身份鑒權的環(huán)節(jié)。

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

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

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

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

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

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

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

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

public T borrow(long timeout, final TimeUnit timeUnit) throws InterruptedException{      // 嘗試從 thread-local 中獲取      final List