p6spy列印sql日誌執行緒不安全導致的生產問題
首先說明下我這個標題可能起的不到位,其實我本次要介紹的是一次生產定位問題的思路及過程。
1.生產現象
國慶前期釋出了一個很小版本,大家都以為沒什麼問題,可是釋出後生產出現了問題並且持續了兩個小時以上,現象如下:
ERROR|org.hibernate.engine.jdbc.spi.SqlExceptionHelper|[SimpleAsyncTaskExecutor-52] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:150; busy:150; idle:0; lastwait:60000].
2.執行緒dump檔案分析
這裡涉及到資訊保安問題,公司內網無法傳送資料,所以本地再現了下,執行緒棧資訊大致如下: 我們線上程棧統計了正在執行的執行緒正好是資料庫連線池的最大數目,這裡我們就開始懷疑HashMap高併發非執行緒安全導致,佔用資料庫連線無法釋放。由於沒有堆資訊進行佐證,我們無法石錘 但是這裡很明顯是p6spy列印sql日誌引起的問題,我們可以到它的官網進行求證https://github.com/p6spy/p6spy/pull/318/commits/bba79de399f862b416db9d476e43f3af33ef90f7
3.問題復現及驗證
1.復現HashMap死迴圈 這裡我參考了倉頡圖解系列文章的復現demo 程式碼如下:
package com.spring.test.deadmap; import java.util.HashMap; import java.util.Map; import java.util.concurrent.atomic.AtomicInteger; public class HashMapThread extends Thread { private static AtomicInteger ai = new AtomicInteger(0); private static Map<Integer, Integer> map = new HashMap<Integer, Integer>(1); public void run() { while (ai.get() < 100000) { map.put(ai.get(), ai.get()); ai.incrementAndGet(); } } }
package com.spring.test.deadmap;
public class Test {
public static void main(String[] args) {
HashMapThread hmt0 = new HashMapThread();
HashMapThread hmt1 = new HashMapThread();
HashMapThread hmt2 = new HashMapThread();
HashMapThread hmt3 = new HashMapThread();
HashMapThread hmt4 = new HashMapThread();
hmt0.start();
hmt1.start();
hmt2.start();
hmt3.start();
hmt4.start();
}
}
使用低版本jdk較容易復現死迴圈,多試幾次。 2.證明執行緒無法結束是因為HashMap存在環 我們需要藉助堆快照形成堆內例項dump檔案,藉助MAT進行分析當前HashMap.Entry[]陣列中的Entry連結串列是否存在迴圈引用 顯然我們當前未結束執行緒的持有HashMap中存在環引用。