摘要:本次分享的是一次關於 MySQL 高可用問題的定位過程,其中曲折頗多但問題自己卻比較有些表明性,遂將其記錄以供參考。
1、背景
近期由測試反饋的問題有點多,其中關於系統可靠性測試提出的問題使人感到頭疼,一來這類問題有時候屬於「偶發」現象,難以在環境上快速復現;二來則是可靠性問題的定位鏈條有時候變得很長,極端狀況下可能要從 A 服務追蹤到 Z 服務,或者是從應用代碼追溯到硬件層面。前端
本次分享的是一次關於 MySQL 高可用問題的定位過程,其中曲折頗多但問題自己卻比較有些表明性,遂將其記錄以供參考。java
架構
首先,本系統以 MySQL 做爲主要的數據存儲部件。整一個是典型的微服務架構(SpringBoot + SpringCloud),持久層則採用了以下幾個組件:node
- mybatis,實現 SQL <-> Method 的映射
- hikaricp,實現數據庫鏈接池
- mariadb-java-client,實現 JDBC 驅動
在 MySQL 服務端部分,後端採用了雙主架構,前端以 keepalived 結合浮動IP(VIP)作一層高可用。以下:mysql
說明算法
- MySQL 部署兩臺實例,設定爲互爲主備的關係。
- 爲每臺 MySQL 實例部署一個 keepalived 進程,由 keepalived 提供 VIP 高可用的故障切換。
實際上,keepalived 和 MySQL 都實現了容器化,而 VIP 端口則映射到 VM 上的 nodePort 服務端口上。spring
- 業務服務一概使用 VIP 進行數據庫訪問。
Keepalived 是基於 VRRP 協議實現了路由層轉換的,在同一時刻,VIP 只會指向其中的一個虛擬機(master)。當主節點發生故障時,其餘的 keepalived 會檢測到問題並從新選舉出新的 master,此後 VIP 將切換到另外一個可用的 MySQL 實例節點上。這樣一來,MySQL 數據庫就擁有了基礎的高可用能力。sql
另一點,Keepalived 還會對 MySQL 實例進行定時的健康檢查,一旦發現 MySQL 實例不可用會將自身進程殺死,進而再觸發 VIP 的切換動做。數據庫
問題現象
本次的測試用例也是基於虛擬機故障的場景來設計的:後端
持續以較小的壓力向業務服務發起訪問,隨後將其中一臺 MySQL 的容器實例(master)重啓。 按照原有的評估,業務可能會產生很小的抖動,但其中斷時間應該保持在秒級。
然而通過屢次的測試後發現,在重啓 MySQL 主節點容器以後,有必定的機率會出現業務卻再也沒法訪問的狀況!網絡
2、分析過程
在發生問題以後,開發同窗的第一反應是 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.<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 的可執行狀態。從命名上看該線程應該是 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<Object> list = threadList.get(); for (int i = list.size() - 1; i >= 0; i--) { ... } // 計算當前等待請求的任務 final int waiting = waiters.incrementAndGet(); try { for (T bagEntry : sharedList) { if (bagEntry.compareAndSet(STATE_NOT_IN_USE, STATE_IN_USE)) { //若是得到了可用鏈接,會觸發填充任務 if (waiting > 1) { listener.addBagItem(waiting - 1); } return bagEntry; } } //沒有可用鏈接,先觸發填充任務 listener.addBagItem(waiting); //在指定時間內等待可用鏈接進入 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(); } }
注意到,不管是有沒有可用鏈接,該方法都會觸發一個 listener.addBagItem() 方法,HikariPool 對該接口的實現以下:
public void addBagItem(final int waiting) { final boolean shouldAdd = waiting - addConnectionQueueReadOnlyView.size() >= 0; // Yes, >= is intentional. if (shouldAdd) { //調用 AddConnectionExecutor 提交建立鏈接的任務 addConnectionExecutor.submit(poolEntryCreator); } else { logger.debug("{} - Add connection elided, waiting {}, queue {}", poolName, waiting, addConnectionQueueReadOnlyView.size()); } } PoolEntryCreator 則實現了建立鏈接的具體邏輯,以下: public class PoolEntryCreator{ @Override public Boolean call() { long sleepBackoff = 250L; //判斷是否須要創建鏈接 while (poolState == POOL_NORMAL && shouldCreateAnotherConnection()) { //建立 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 採用了單線程的設計,當產生新鏈接需求時,會異步觸發 PoolEntryCreator 任務進行補充。其中 PoolEntryCreator. createPoolEntry() 會完成 MySQL 驅動鏈接創建的全部事情,而咱們的狀況則偏偏是 MySQL 建鏈過程產生了永久性阻塞。所以不管後面怎麼獲取鏈接,新來的建鏈任務都會一直排隊等待,這便致使了業務上一直沒有鏈接可用。
下面這個圖說明了 hikariCP 的建鏈過程:
好了,讓咱們在回顧一下前面關於可靠性測試的場景:
首先,MySQL 主實例發生故障,而緊接着 hikariCP 則檢測到了壞的鏈接(connection is dead)並將其釋放,在釋放關閉鏈接的同時又發現鏈接數須要補充,進而當即觸發了新的建鏈請求。
而問題就恰好出在這一次建鏈請求上,TCP 握手的部分是成功了(客戶端和 MySQL VM 上 nodePort 完成鏈接),但在接下來因爲當前的 MySQL 容器已經中止(此時 VIP 也切換到了另外一臺 MySQL 實例上),所以客戶端再也沒法得到原 MySQL 實例的握手包響應(該握手屬於MySQL應用層的協議),此時便陷入了長時間的阻塞式 socketRead 操做。而建鏈請求任務偏偏好採用了單線程運做,進一步則致使了全部業務的阻塞。
3、解決方案
在瞭解了事情的前因後果以後,咱們主要考慮從兩方面進行優化:
- 優化一,增長 HirakiPool 中 AddConnectionExecutor 線程的數量,這樣即便第一個線程出現掛死,還有其餘的線程能參與建鏈任務的分配。
- 優化二,出問題的 socketRead 是一種同步阻塞式的調用,可經過 SO_TIMEOUT 來避免長時間掛死。
對於優化點一,咱們一致認爲用處並不大,若是鏈接出現了掛死那麼至關於線程資源已經泄露,對服務後續的穩定運行十分不利,並且 hikariCP 在這裏也已經將其寫死了。所以關鍵的方案仍是避免阻塞式的調用。
查閱了 mariadb-java-client 官方文檔後,發現能夠在 JDBC URL 中指定網絡IO 的超時參數,以下:
具體參考:https://mariadb.com/kb/en/about-mariadb-connector-j/
如描述所說的,socketTimeout 能夠設置 socket 的 SO_TIMEOUT 屬性,從而達到控制超時時間的目的。默認是 0,即不超時。
咱們在 MySQL JDBC URL 中加入了相關的參數,以下:
spring.datasource.url=jdbc:mysql://10.0.71.13:33052/appdb?socketTimeout=60000&connectTimeout=30000&serverTimezone=UTC
此後對 MySQL 可靠性場景進行屢次驗證,發現鏈接掛死的現象已經再也不出現,此時問題獲得解決。
4、小結
本次分享了一次關於 MySQL 鏈接掛死問題排查的心路歷程,因爲環境搭建的工做量巨大,並且該問題復現存在偶然性,整個分析過程仍是有些坎坷的(其中也踩了坑)。的確,咱們很容易被一些表面的現象所迷惑,而以爲問題很難解決時,更容易帶着偏向性思惟去處理問題。例如本例中曾一致認爲鏈接池出現了問題,但實際上倒是因爲 MySQL JDBC 驅動(mariadb driver)的一個不嚴謹的配置所致使。
從原則上講,應該避免一切可能致使資源掛死的行爲。若是咱們能在前期對代碼及相關配置作好充分的排查工做,相信 996 就會離咱們愈來愈遠。
本文分享自華爲雲社區《MySQL 鏈接爲何掛死了?》,原文做者:TANG卓章 。