詳解MySQL連接掛死的原因

一、背景

近期由測試反饋的問題有點多,其中關於系統可靠性測試提出的問題令人感到頭疼,一來這類問題有時候屬於“偶發”現象,難以在環境上快速復現;二來則是可靠性問題的定位鏈條有時候變得很長,極端情況下可能要從 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.<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 操作。而建鏈請求任務恰恰好采用瞭單線程運作,進一步則導致瞭所有業務的阻塞。

三、解決方案

在瞭解瞭事情的來龍去脈之後,我們主要考慮從兩方面進行優化:

  • 優化一,增加 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 可靠性場景進行多次驗證,發現連接掛死的現象已經不再出現,此時問題得到解決。

四、小結

本次分享瞭一次關於 MySQL 連接掛死問題排查的心路歷程,由於環境搭建的工作量巨大,而且該問題復現存在偶然性,整個分析過程還是有些坎坷的(其中也踩瞭坑)。的確,我們很容易被一些表面的現象所迷惑,而覺得問題很難解決時,更容易帶著偏向性思維去處理問題。例如本例中曾一致認為連接池出現瞭問題,但實際上卻是由於 MySQL JDBC 驅動(mariadb driver)的一個不嚴謹的配置所導致。

從原則上講,應該避免一切可能導致資源掛死的行為。如果我們能在前期對代碼及相關配置做好充分的排查工作,相信 996 就會離我們越來越遠。

以上就是詳解MySQL連接掛死的原因的詳細內容,更多關於MySQL連接掛死的原因的資料請關註WalkonNet其它相關文章!

推薦閱讀: