歡迎光臨
每天分享高質量文章

【追光者系列】HikariCP詭異問題撥開迷霧推理破案實錄(下)

摘自【工匠小豬豬的技術世界】 1.這是一個系列,有興趣的朋友可以持續關註 2.如果你有HikariCP使用上的問題,可以給我留言,我們一起溝通討論 3.希望大家可以提供我一些案例,我也希望可以支持你們做一些調優


本文是 【追光者系列】HikariCP詭異問題撥開迷霧推理破案實錄(上)的下半部分

直奔疑點

首先我直接懷疑是不是資料庫斷掉了連接,於是登上了資料庫查詢了資料庫引數,結果是沒毛病。

為了穩妥起見,我又咨詢了DBA,DBA說線下環境和線上環境引數一樣,並幫我看了,沒有任何問題。

為什麼我直接奔向這個疑點,因為《Solr權威指南》的作者蘭小偉大佬曾經和我分享過一個案例:他前段時間也遇到類似的問題,他用的是c3p0,碰到和我一樣的碰到一樣的exception,那個異常是服務器主動關閉了鏈接,而客戶端還拿那個鏈接去操作,大佬加個testQuery,保持心跳即可解決。c3p0設置一個周期,是定時主動檢測的。

估計是mysql服務器端鏈接快取時間設置的太短,服務器端主動銷毀了鏈接,一般做法是客戶端連接池配置testQuery。 testQuery我覺得比較影響hikariCP的性能,所以我決定跟一下原始碼瞭解一下原理並定位問題。

撥開迷霧

按著上一篇的推測,我們在Hikari核心原始碼中打一些日誌記錄。

第一處,在com.zaxxer.hikari.pool.HikariPool#getConnection中增加IDEA log expression

  1. public Connection getConnection(final long hardTimeout) throws SQLException {

  2.      suspendResumeLock.acquire();

  3.      final long startTime = currentTime();

  4.      try {

  5.         long timeout = hardTimeout;

  6.         PoolEntry poolEntry = null;

  7.         try {

  8.            do {

  9.               poolEntry = connectionBag.borrow(timeout, MILLISECONDS);

  10.               if (poolEntry == null) {

  11.                  break; // We timed out... break and throw exception

  12.               }

  13.               final long now = currentTime();

  14.               if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > ALIVE_BYPASS_WINDOW_MS && !isConnectionAlive(poolEntry.connection))) {

  15.                  closeConnection(poolEntry, "(connection is evicted or dead)"); // Throw away the dead connection (passed max age or failed alive test)

  16.                  timeout = hardTimeout - elapsedMillis(startTime);

  17.               }

  18.               else {

  19.                  metricsTracker.recordBorrowStats(poolEntry, startTime);

  20.                  return poolEntry.createProxyConnection(leakTask.schedule(poolEntry), now);

  21.               }

  22.            } while (timeout > 0L);

  23.            metricsTracker.recordBorrowTimeoutStats(startTime);

  24.         }

  25.         catch (InterruptedException e) {

  26.            if (poolEntry != null) {

  27.               poolEntry.recycle(startTime);

  28.            }

  29.            Thread.currentThread().interrupt();

  30.            throw new SQLException(poolName + " - Interrupted during connection acquisition", e);

  31.         }

  32.      }

  33.      finally {

  34.         suspendResumeLock.release();

  35.      }

  36.      throw createTimeoutException(startTime);

  37.   }

我們對於直接拋異常的代碼的條件判斷入口處增加除錯信息

  1. if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > ALIVE_BYPASS_WINDOW_MS && !isConnectionAlive(poolEntry.connection)))code> <code class="">String.format("Evicted: %s; enough time elapse: %s;poolEntrt: %s;", poolEntry.isMarkedEvicted(), elapsedMillis(poolEntry.lastAccessed, now) > ALIVE_BYPASS_WINDOW_MS,poolEntry);

第二處、在com.zaxxer.hikari.pool.HikariPool#softEvictConnection處增加除錯信息

  1. private boolean softEvictConnection(final PoolEntry poolEntry, final String reason, final boolean owner) {

  2.      poolEntry.markEvicted();

  3.      if (owner || connectionBag.reserve(poolEntry)) {

  4.         closeConnection(poolEntry, reason);

  5.         return true;

  6.      }

  7.      return false;

  8.   }

  9.  

  10.   String.format("Scheduled soft eviction for connection %s is due; owner %s is;", poolEntry.connection,owner)

為什麼要打在softEvictConnection這裡呢?因為在createPoolEntry的時候註冊了一個延時任務,並通過poolEntry.setFutureEol設置到poolEntry中 softEvictConnection,首先標記markEvicted。然後如果是用戶自己呼叫的,則直接關閉連接;如果從connectionBag中標記不可borrow成功,則關閉連接。

這個定時任務是在每次createPoolEntry的時候,根據maxLifetime隨機設定一個variance,在maxLifetime – variance之後觸發evict。

  1.  /**

  2.    * Creating new poolEntry.

  3.    */

  4.   private PoolEntry createPoolEntry() {

  5.      try {

  6.         final PoolEntry poolEntry = newPoolEntry();

  7.         final long maxLifetime = config.getMaxLifetime();

  8.         if (maxLifetime > 0) {

  9.            // variance up to 2.5% of the maxlifetime

  10.            final long variance = maxLifetime > 10_000 ? ThreadLocalRandom.current().nextLong( maxLifetime / 40 ) : 0;

  11.            final long lifetime = maxLifetime - variance;

  12.            poolEntry.setFutureEol(houseKeepingExecutorService.schedule(

  13.               () -> {

  14.                  if (softEvictConnection(poolEntry, "(connection has passed maxLifetime)", false /* not owner */)) {

  15.                     addBagItem(connectionBag.getWaitingThreadCount());

  16.                  }

  17.               },

  18.               lifetime, MILLISECONDS));

  19.         }

  20.         return poolEntry;

  21.      }

  22.      catch (Exception e) {

  23.         if (poolState == POOL_NORMAL) {

  24.            LOGGER.debug("{} - Cannot acquire connection from data source", poolName, (e instanceof ConnectionSetupException ? e.getCause() : e));

  25.         }

  26.         return null;

  27.      }

  28.   }

守株待兔

做瞭如上處理之後我們就安心得等結果

很快來了一組資料,我們可以看到確實poolEntry.isMarkedEvicted()一直都是false,(elapsedMillis(poolEntry.lastAccessed, now) > ALIVEBYPASSWINDOW_MS這個判斷為true。

sharedlist 是 CopyOnWriteArrayList,每次getConnection都是陣列首

softEvictConnection這裡的信息在20分鐘到了的時候也出現了

從這張圖我們可以看到,owner是false,第一個觸發定時任務的也正好是第一個連接。刪除的那個就是每次微服務健康檢測healthcheck連接用的那個。

我仔細數了一下,確實一共創建了十次SSL,也就是本次周期確實重新連了十次資料庫TCP連接。那麼問題來了,為什麼每次正好是8次或者9次異常日誌?

抽絲剝繭

定時任務的執行時間是多少?

這個定時任務是在每次createPoolEntry的時候,根據maxLifetime隨機設定一個variance,在maxLifetime – variance之後觸發evict。 maxLifetime我現在設置的是20分鐘,

  1. // variance up to 2.5% of the maxlifetime

  2.            final long variance = maxLifetime > 10_000 ? ThreadLocalRandom.current().nextLong( maxLifetime / 40 ) : 0;

  3.            final long lifetime = maxLifetime - variance

按照20分鐘1200秒來算,這個evict的操作是1170秒左右,按理說離20分鐘差30秒左右。

但是通過觀察,好像第一個連接創建的時間比其他連接快 4 秒。

也就是說時間上被錯開了,本來10個連接是相近的時間close的,第一個連接先被定時器close了,其他連接是getconnection的時候close的,這樣就造成了一個迴圈。其他連接是getconnection的時候幾乎同時被關閉的,就是哪些warn日誌出現的時候。

這猜想和我debug得到的結果是一致的,第一個getConnection健康監測是被定時器close的,close之後立馬fillpool,所以warn的是小於10的。和我們看到的歷史資料一樣,8為主,也有9。

定時器close之後的那個新連接,會比其他的連接先進入定時器的調度,其他的9個被迴圈報錯關閉。

getconnection時報錯關閉的那些連接,跟被定時器關閉的連接的定時器時間錯開,如上圖所示,有兩個連接已經處於remove的狀態了。

9次是比較好解釋的,第一個連接是同步創建的,建構式里呼叫checkFailFast會直接建一個連接,其他連接是 housekeeper里異步fillpool創建的。

做了一次測試,這一波果然打了9次日誌

那麼9次就可以這麼合理的解釋了。

8次的解釋應該就是如上圖所示2個已經被remove掉的可能性情況。

柳暗花明

這時小手一抖,netstat了一把

發現很快就closewait了,而closewait代表已經斷開了,基本不能再用了。其實就是被對方斷開了。

這時我又找了DBA,告訴他我得到的結論,DBA再次幫我確認之後,焦急的等待以後,屏幕那頭給我這麼一段回覆:

這時叫了一下配置中心的同學一起看了一下這個資料庫的地址,一共有5個配置連到了這個廢棄的proxy,和我們線上出問題的數目和應用基本一致!

配置中心的同學和DBA說這個proxy曾經批量幫業務方改過,有些業務方居然又改回去了。。。。這時業務方的同學也說話了,“難怪我navicate 在proxy上edit一個表要等半天。。stable環境就秒出”

真相大白

修改了這個廢棄的proxy改為真正的資料庫地址以後,第二天業務方的同學給了我們反饋:

圖左邊2個綠色箭頭,下麵那個是調整過配置的環境,上面是沒有調整的,調整過的今天已經沒有那個日誌了,那17.6%是正常的業務日誌。

END

赞(0)

分享創造快樂