> 宣告：本文為博主原創文章，由於已授權部分平臺發表該文章（知乎、雲社群），可能造成釋出時間方面的困擾。 ## 一、背景 近期由測試反饋的問題有點多，其中關於系統可靠性測試提出的問題令人感到頭疼，一來這類問題有時候屬於“偶發”現象，難以在環境上快速復現；二來則是可靠性問題的定位鏈條有時候變得很長，極端情況下可能要從 A 服務追蹤到 Z 服務，或者是從應用程式碼追溯到硬體層面。 本次分享的是一次關於 MySQL 高可用問題的定位過程，其中曲折頗多但問題本身卻比較有些代表性，遂將其記錄以供參考。 ### 架構 首先，本系統以 MySQL 作為主要的資料儲存部件。整一個是典型的微服務架構（SpringBoot + SpringCloud），持久層則採用瞭如下幾個元件： - mybatis，實現 SQL <-> Method 的對映 - hikaricp，實現資料庫連線池 - mariadb-java-client，實現 JDBC 驅動 在 MySQL 服務端部分，後端採用了雙主架構，前端以 keepalived 結合浮動IP（VIP）做一層高可用。如下：  **說明** - MySQL 部署兩臺例項，設定為互為主備的關係。 - 為每臺 MySQL 例項部署一個 keepalived 程序，由 keepalived 提供 VIP 高可用的故障切換。 實際上，keepalived 和 MySQL 都實現了容器化，而 VIP 埠則對映到 VM 上的 nodePort 服務埠上。 - 業務服務一律使用 VIP 進行資料庫訪問。 Keepalived 是基於 VRRP 協議實現了路由層轉換的，在同一時刻，VIP 只會指向其中的一個虛擬機器（master）。當主節點發生故障時，其他的 keepalived 會檢測到問題並重新選舉出新的 master，此後 VIP 將切換到另一個可用的 MySQL 例項節點上。這樣一來，MySQL 資料庫就擁有了基礎的高可用能力。 另外一點，Keepalived 還會對 MySQL 例項進行定時的健康檢查，一旦發現 MySQL 例項不可用會將自身程序殺死，進而再觸發 VIP 的切換動作。 ### 問題現象 本次的測試用例也是基於虛擬機器故障的場景來設計的： ``` 持續以較小的壓力向業務服務發起訪問，隨後將其中一臺 MySQL 的容器例項(master)重啟。 按照原有的評估，業務可能會產生很小的抖動，但其中斷時間應該保持在秒級。 ``` 然而經過多次的測試後發現，在重啟 MySQL 主節點容器之後，有一定的概率會出現業務卻再也無法訪問的情況！ ## 二、分析過程 在發生問題之後，開發同學的第一反應是 MySQL 的高可用機制出了問題。由於此前曾經出現過由於 keepalived 配置不當導致 VIP 未能及時切換的問題，因此對其已經有所戒備。 先是經過一通的排查，然後並沒有找到 keepalived 任何配置上的毛病。 然後在沒有辦法的情況下，重新測試了幾次，問題又復現了。 緊接著，我們提出了幾個疑點： 1. **Keepalived 會根據 MySQL 例項的可達性進行判斷，會不會是健康檢查出了問題？** 但在本次測試場景中，MySQL 容器銷燬會導致 keepalived 的埠探測產生失敗，這同樣會導致 keepalived 失效。如果 keepalived 也發生了中止，那麼 VIP 應該能自動發生搶佔。而通過對比兩臺虛擬機器節點的資訊後，發現 VIP 的確發生了切換。 2. **業務程序所在的容器是否發生了網路不可達的問題？** 嘗試進入容器，對當前發生切換後的浮動IP、埠執行 telnet 測試，發現仍然能訪問成功。 ### 連線池排查 在排查前面兩個疑點之後，我們只能將目光轉向了業務服務的DB客戶端上。 從日誌上看，在產生故障的時刻，業務側的確出現了一些異常，如下： ``` 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!/:?] ... ``` 這裡提示的是業務操作獲取連線超時了（超過了30秒）。那麼，會不會是連線數不夠用呢？ > 業務接入採用的是 hikariCP 連線池，這也是市面上流行度很高的一款元件了。 我們隨即檢查了當前的連線池配置，如下： ``` //最小空閒連線數 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，也就是說，就算在沒有任何業務的情況下，連線池應該保證有 10 個連線。更何況當前的業務訪問量極低，不應該存在連線數不夠使用的情況。 除此之外，另外一種可能性則可能是出現了“殭屍連線”，也就是說在重啟的過程中，連線池一直沒有釋放這些不可用的連線，最終造成沒有可用連線的結果。 開發同學對"殭屍連結"的說法深信不疑，傾向性的認為這很可能是來自於 HikariCP 元件的某個 BUG.. 於是開始走讀 HikariCP 的原始碼，發現應用層向連線池請求連線的一處程式碼如下： ``` public class HikariPool{ //獲取連線物件入口 public Connection getConnection(final long hardTimeout) throws SQLException { suspendResumeLock.acquire(); final long startTime = currentTime(); try { //使用預設的30s 超時時間 long timeout = hardTimeout; do { //進入迴圈，在指定時間內獲取可用連線 //從 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); //由於可用連線變少，將觸發填充連線池的任務 if (poolState == POOL_NORMAL) { fillPool(); } }); } } ``` 注意到，只有當連線滿足下面條件中的其中一個時，會被執行 close。 - isMarkedEvicted() 的返回結果是 true，即標記為清除 如果連線存活時間超出最大生存時間(maxLifeTime)，或者距離上一次使用超過了idleTimeout，會被定時任務標記為清除狀態，清除狀態的連線在獲取的時候才真正 close。 - 500ms 內沒有被使用，且連線已經不再存活，即 isConnectionAlive() 返回 false 由於我們把 idleTimeout 和 maxLifeTime 都設定得非常大，因此需重點檢查 isConnectionAlive 方法中的判斷，如下： ``` public class PoolBase{ //判斷連線是否存活 boolean isConnectionAlive(final Connection connection) { try { try { //設定 JDBC 連線的執行超時 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) { //發生異常時，將失敗資訊記錄到上下文 lastConnectionFailure.set(e); logger.warn("{} - Failed to validate connection {} ({}). Possibly consider using a shorter maxLifetime value.", poolName, connection, e.getMessage()); return false; } } } ``` 我們看到，在PoolBase.isConnectionAlive 方法中對連線執行了一系列的探測，如果發生異常還會將異常資訊記錄到當前的執行緒上下文中。隨後，在 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; } ``` 這裡的異常訊息和我們在業務服務中看到的異常日誌基本上是吻合的，即除了超時產生的 "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!/:?] ``` 到這裡，我們已經將應用獲得連線的程式碼大致梳理了一遍，整個過程如下圖所示：  從執行邏輯上看，連線池的處理並沒有問題，相反其在許多細節上都考慮到位了。在對非存活連線執行 close 時，同樣呼叫了 removeFromBag 動作將其從連線池中移除，因此也不應該存在殭屍連線物件的問題。 那麼，我們之前的推測應該就是錯誤的！ ### 陷入焦灼 在程式碼分析之餘，開發同學也注意到當前使用的 hikariCP 版本為 3.4.5，而環境上出問題的業務服務卻是 2.7.9 版本，這彷彿預示著什麼.. 讓我們再次假設 hikariCP 2.7.9 版本存在某種未知的 BUG，導致了問題的產生。 為了進一步分析連線池對於服務端故障的行為處理，我們嘗試在本地機器上進行模擬，這一次使用了 hikariCP 2.7.9 版本進行測試，並同時將 hikariCP 的日誌級別設定為 DEBUG。 模擬場景中，會由 由本地應用程式連線本機的 MySQL 資料庫進行操作，步驟如下： ``` 1. 初始化資料來源，此時連線池 min-idle 設定為 10； 2. 每隔50ms 執行一次SQL操作，查詢當前的元資料表； 3. 將 MySQL 服務停止一段時間，觀察業務表現； 4. 將 MySQL 服務重新啟動，觀察業務表現。 ``` 最終產生的日誌如下： ``` //初始化過程，建立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) //執行業務操作，成功 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) //嘗試建立連線失敗 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:?] ... //持續失敗.. 直到MySQL重啟 //重啟後，自動建立連線成功 DEBUG -HikariPool$PoolEntryCreator.call -Added connection MariaDbConnection@42c5503e DEBUG -HikariPool$PoolEntryCreator.call -Added connection MariaDbConnection@695a7435 //連線池狀態，重新建立10個連線 DEBUG -HikariPool.logPoolState(HikariPool.java:421) -After adding stats (total=10, active=1, idle=9, waiting=0) //執行業務操作，成功（已經自愈） execute statement: true ``` 從日誌上看，hikariCP 還是能成功檢測到壞死的連線並將其踢出連線池，一旦 MySQL 重新啟動，業務操作又能自動恢復成功了。根據這個結果，基於 hikariCP 版本問題的設想也再次落空，研發同學再次陷入焦灼。 ### 撥開雲霧見光明 多方面求證無果之後，我們最終嘗試在業務服務所在的容器內進行抓包，看是否能發現一些蛛絲馬跡。 進入故障容器，執行 ***tcpdump -i eth0 tcp port 30052*** 進行抓包，然後對業務介面發起訪問。 此時令人詭異的事情發生了，沒有任何網路包產生！而業務日誌在 30s 之後也出現了獲取連線失敗的異常。 我們通過 netstat 命令檢查網路連線，發現只有一個 ESTABLISHED 狀態的 TCP 連線。  也就是說，當前業務例項和 MySQL 服務端是存在一個建好的連線的，但為什麼業務還是報出可用連線呢？ 推測可能原因有二： - 該連線被某個業務（如定時器）一直佔用。 - 該連線實際上還沒有辦法使用，可能處於某種僵死的狀態。 對於原因一，很快就可以被推翻，一來當前服務並沒有什麼定時器任務，二來就算該連線被佔用，按照連線池的原理，只要沒有達到上限，新的業務請求應該會促使連線池進行新連線的建立，那麼無論是從 netstat 命令檢查還是 tcpdump 的結果來看，不應該一直是隻有一個連線的狀況。 那麼，情況二的可能性就很大了。帶著這個思路，繼續分析 Java 程序的執行緒棧。 執行 kill -3 pid 將執行緒棧輸出後分析，果不其然，在當前 thread stack 中發現瞭如下的條目： ``` "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 的可執行狀態。從命名上看該執行緒應該是 HikariCP 連線池用於建立連線的任務執行緒，socket 讀操作則來自於 MariaDbConnection.newConnection() 這個方法，即 mariadb-java-client 驅動層建立 MySQL 連線的一個操作，其中 ReadInitialHandShakePacket 初始化則屬於 MySQL 建鏈協議中的一個環節。 簡而言之，上面的執行緒剛好處於建鏈的一個過程態，關於 mariadb 驅動和 MySQL 建鏈的過程大致如下：  MySQL 建鏈首先是建立 TCP 連線（三次握手），客戶端會讀取 MySQL 協議的一個初始化握手訊息包，內部包含 MySQL 版本號，鑑權演算法等等資訊，之後再進入身份鑑權的環節。 這裡的問題就在於 ReadInitialHandShakePacket 初始化（讀取握手訊息包）一直處於 socket read 的一個狀態。 如果此時 MySQL 遠端主機故障了，那麼該操作就會一直卡住。而此時的連線雖然已經建立（處於 ESTABLISHED 狀態），但卻一直沒能完成協議握手和後面的身份鑑權流程，即該連線只能算一個**半成品**（無法進入 hikariCP 連線池的列表中）。從故障服務的 DEBUG 日誌也可以看到，連線池持續是沒有可用連線的，如下： ``` DEBUG HikariPool.logPoolState --> Before cleanup stats (total=0, active=0, idle=0, waiting=3) ``` 另一個需要解釋的問題則是，這樣一個 socket read 操作的阻塞是否就造成了整個連線池的阻塞呢？ 經過程式碼走讀，我們再次梳理了 hikariCP 建立連線的一個流程，其中涉及到幾個模組： - HikariPool，連線池例項，由該物件連線的獲取、釋放以及連線的維護。 - ConnectionBag，連線物件容器，存放當前的連線物件列表，用於提供可用連線。 - AddConnectionExecutor，新增連線的執行器，命名如 "HikariPool-1 connection adder"，是一個單執行緒的執行緒池。 - PoolEntryCreator，新增連線的任務，實現建立連線的具體邏輯。 - HouseKeeper，內部定時器，用於實現連線的超時淘汰、連線池的補充等工作。 HouseKeeper 在連線池初始化後的 100ms 觸發執行，其呼叫 fillPool() 方法完成連線池的填充，例如 min-idle 是10，那麼初始化就會建立10個連線。ConnectionBag 維護了當前連線物件的列表，該模組還維護了請求連線者(waiters)的一個計數器，用於評估當前連線數的需求。 其中，borrow 方法的邏輯如下： ``` public T borrow(long timeout, final TimeUnit timeUnit) throws InterruptedException { // 嘗試從 thread-local 中獲取 final List