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

---

問題描述

2018年4月19日早上，有業務方反饋每半小時都會打出如下異常：

HikariPool-1 - Failed to validate connection com.mysql.jdbc.JDBC4Connection@7174224b (No operations allowed after connection closed.)

業務方的需求是：這種日誌需要配置能夠消除？我能如何調優引數才能關閉這些日誌？是不是我的hikariCP的connectionTimeout是不是每個業務的查詢超時時間？

首先解釋一下connectionTimeout的意思，這並不是獲取連線的超時時間，而是從連線池傳回連線的超時時間。SQL執行的超時時間，JDBC 可以直接使用 Statement.setQueryTimeout，Spring 可以使用@Transactional(timeout=10)。

維護HikariCP相關的中介軟體也有8個月的時間了，我知道該異常其實是不影響業務的，但是這8個月期間經常不斷的有業務方諮詢同一個問題，所以我覺得很有必要認真地梳理一下該問題原始碼級的具體原理及根本原因來給業務方一個合理的交代。

望聞問切

進行了一波詳細的勘查，又拿到瞭如下資訊

• 該業務沒有上線，線上下環境暴露出的問題

• 線上服務查了幾個服務沒有這樣的問題

• 業務方一開始說線下環境50～100QPS，但是實際業務方並沒有呼叫

• springboot微服務的health check我司每10秒執行一次，可以理解為進行一次getConnection操作

• 業務方沒有做任何配置，hikariCP的預設maxLifetime是30分鐘，和業務方的表象吻合

• 波及業務線下掃出了五個應用有同樣的問題

• 拉取業務方程式碼debug，maxLifetime調整為20分鐘，該異常也平均是20分鐘輸出一次

• hikariCP的maximumPoolSize為10，按理說異常也應該是10，但是實際是大多落在8左右，也有可能是9，極小情況是11。當調小maxLifetime為一分鐘時，異常數目每階段時間出現暴增現象。

採用了kibana協助排查問題，得到的資訊如下：

如下圖所示，平均每半小時出現一波異常，規律性很強，20:00時由於我將maxLifetime調整為一分鐘，異常數目飆升，之後我把maxLifetime調整為二十分鐘，就呈現出每20分鐘出現一波異常

HikariPool-1 - Failed to validate connection com.mysql.jdbc.JDBC4Connection@7174224b (No operations allowed after connection closed.) 

具體異常我抽樣以後展示如下，按照時間倒序排列，之前是預設30分鐘，後面調整為20分鐘：

brettw如是說

在stackoverflow已經有使用者提出了同樣類似的問題：

https://stackoverflow.com/questions/41008350/no-operations-allowed-after-connection-closed-errors-in-slick-hikaricp

該使用者每3秒執行一次查詢，每次查詢的時間都小於0.4s。起初一切執行正常，但大約2小時後，HikariCP開始關閉連線，導致關於’no operations allowed after connection closed’的錯誤：

15:20:38.288 DEBUG [] [rdsConfig-8] com.zaxxer.hikari.pool.HikariPool - rdsConfig - Timeout failure stats (total=30, active=0, idle=30, waiting=0)
15:20:38.290 DEBUG [] [rdsConfig connection closer] com.zaxxer.hikari.pool.PoolBase - rdsConfig - Closing connection com.mysql.jdbc.JDBC4Connection@229960c: (connection is evicted or dead)
15:20:38.333 DEBUG [] [rdsConfig connection closer] com.zaxxer.hikari.pool.PoolBase - rdsConfig - Closing connection com.mysql.jdbc.JDBC4Connection@229960c failed
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_77]
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source) ~[na:1.8.0_77]
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source) ~[na:1.8.0_77]
    at java.lang.reflect.Constructor.newInstance(Unknown Source) ~[na:1.8.0_77]

該使用者也是期望怎麼配置來避免此情況？這和我的業務方的訴求是完全一致的。該使用者並不理解HikariCP關閉連線的原理，非常困惑。所以我們很有必要給使用者一個交代。

作者表示，HikariCP在使用時不會關閉連線。如果使用中的連線到達，maxLifetime它將被標記為驅逐，並且在下一次執行緒嘗試借用它時將被驅逐。

如上圖所示，作者說明在五種情況下HikariCP會關閉連線，分別是連線驗證失敗、連線閑置時間超過idleTimeout、一個連線到達了它maxLifetime、使用者手動驅逐連線、一個JDBC呼叫丟擲一個不可恢復的 SQLException。每一種情況都會列印不一樣的異常，

有人去看醫生，說他拉肚子了，那醫生能開一樣的藥麼？引起腹瀉原因很多,比如肚子受涼、飲食不衛生、消化不良、食物過敏、感染病毒。針對不同的癥狀要採用不同的治療手段。

同理，雖然都是No operations allowed after connection closed，該使用者是打出了connection is evicted or dead，屬於第三種情況 A connection reached its maxLifetime，而我們的異常是這樣的，和該使用者的提問其實不一樣的，我們命中的是第一種情況 The connection failed validation

HikariPool-1 - Failed to validate connection com.mysql.jdbc.JDBC4Connection@50962fdc (No operations allowed after connection closed.)

作者提及This is invisible to your application.這對應用程式是不可見的，可見這不是一個問題。 但是總讓業務方打日誌也不是一個辦法？不給業務方一個交代也是不行的。更何況只有線下才有這樣頻繁的日誌，線上是沒有的，這其中必有貓膩。

Be MECE

曾經讀過一篇文章提及了 Be MECE MECE取自“Mutually Exclusive Collectively Exhaustive”，中文意思是相互獨立，完全窮盡，發音讀作“Me See”。起源於麥肯錫的一位資深諮詢顧問巴巴拉·明託，她在《金字塔原理》中第一次將這個概念提出，成為後來戰略諮詢行業的重要原則之一。

相互獨立，意味著將能夠影響問題的原因拆分成有明確區分，互不重疊的各個因素。完全窮盡，意味著全面周密，毫無遺漏。

通常運用MECE都是從一個最高層的問題開始，逐層向下進行分解。首先列出你亟待解決的問題，然後將問題拆分成子問題，並保證它們之間互不重疊和幹擾。同時保證你把能夠想到的子問題全部列了出來。

實際運用中你只用不停問自己兩個問題：

1. 我是不是把所有的可能因素都考慮到了，有沒有遺漏的？如果有，再去找。

2. 這些因素之間有沒有互相重疊的部分？如果有，進行去重。

舉個例子，比如你現在遇到的問題是：“我該不該現在跳槽？” 那麼對這個問題的分解可以如下圖所示：

那我們按照這個思路也來分解一下：

1. 是不是這幾個服務依賴的中介軟體版本不同導致的？

2. 是不是資料庫給斷掉了？

3. 兩種情況：被外部關閉了、有程式碼操作了內部的connection物件，是哪種情況乾的？

4. 異常是哪裡丟擲來的？

針對這些疑點，我們來分析一下：

1. 半年來經常有業務方諮詢此問題，根據出問題的五個應用，發現分佈在三種主流版本里

2. 登陸業務方資料庫，show variables like ‘%timeout%’，發現mysql引數並沒有問題，諮詢了DBA，線下也沒有做什麼修改

3. 基本可以排除第一種情況，操作了內部的connection物件可能性比較大

4. 異常是setNetworkTimeout裡面丟擲來的，實現類是JDBC4Connection connectionimpl ping的時候報錯了。mysql把isvalid方法裡的錯誤吃掉了比較坑，isvalid方法裡面報錯了會呼叫close方法，然後hikari外層又調了一次settimeout就觸發了這個warn

大膽猜想

1. HikariCP使用List來儲存開啟的Statement，當Statement關閉或Connection關閉時需要將對應的Statement從List中移除。FastList是從陣列的尾部開始遍歷。CopyOnWriteArrayList負責存放ConcurrentBag中全部用於出借的資源，getConnection方法borrow正是ConcurrentBag的CopyOnWriteArrayList，copyonwrite是拿的陣列首。所以健康檢測下低QPS下連線池取出物件永遠是從CopyOnWriteArrayList sharedList陣列的首部取出的那個？

2. 結合第一點猜想，陣列中的其他連線（除了隊首的），可能在10～20分鐘之內已經被mysql斷掉了？

3. 需要把原始碼中核心操作流程裡的物件都打印出來，去觀察拿到更多的信？

4. 一分鐘沒事，20分鐘 30分鐘有事，是不是因為一分鐘資料庫沒有斷掉？而20～30分鐘的卻已經斷掉了？需要結合mysql的資訊去看

5. 線上高QPS所有連線都處於和資料庫活躍的連線及切換狀態，所以異常遠遠小於線下的原因是，只有陣列首部取出的那個和資料庫互動的流程？

6. 陣列首以外的一些連線是否被內部的connection操作了

撥開迷霧

鑒於篇幅原因，請大家關註明天更新的第二篇《【追光者系列】HikariCP詭異問題撥開迷霧推理破案實錄（下）》，敬請期待！

END

Charles

贊賞

長按二維碼向我轉賬

受蘋果公司新規定影響，微信 iOS 版的贊賞功能被關閉，可透過二維碼轉賬支援公眾號。

閱讀原文


微信掃一掃
使用小程式
即將開啟”“小程式
取消
開啟