阿里Druid資料連線池引發的線上異常解決

2022-03-05 16:01:24

前言

事件起因：專案使用了activiti工作流，系統是由老的spring mvc專案改造成的spring boot專案，資料庫連結池從dbcp切換到druid，新系統上線後，同事多次系統隔一段時間後資料查詢就很慢，基本出不來。

由此開始了線上bug排查之路。這個問題從一開始就模糊定位到資料庫層面的問題，因為只有和資料相關的操作會很慢，其他服務不受影響，並且在中午休息時沒有問題，在下午剛上班後不就出現。

過程一：定位工作流

首先第一反應是看紀錄檔：紀錄檔一切正常，並沒有任何異常資訊丟擲，然後將紀錄檔級別調整到debug，發現了一些問題，中午休息時，使用者沒有操作的情況下，紀錄檔一直在輸出jpa的連線資訊，最後定位是工作流的非同步執行器在輪詢，因為在spring boot環境下spring.activiti.async-executor-activate=true預設是true的，如果不需要使用可以設定為false，改完後情況依舊

過程二：定位JPA的OpenEntityManagerInViewInterceptor

使用OpenEntityManagerInViewInterceptor後伺服器端在接收到一個請求的時候開啟EntityManager，在請求結束的時候才去關閉這個EntityManager，所以在使用者數多，並行高，操作耗時的情況下會造成資料連線不夠用的情況，而我們的業務有這個特徵。

在spring boot環境中，OpenEntityManagerInViewInterceptor預設是開啟的，然而我們使用spring.jpa.open-in-view=false關閉後，問題依舊，不過比之前的間隔時間久一點了

過程三：定位Druid，真正的罪魁禍首

使用top定位到程式pid，然後使用jstack -l 2591 >>dump.out 拿到當前堆疊快照後發現如下

"http-nio-8080-exec-54" daemon prio=10 tid=0x0000000000e61000 nid=0xcc9 waiting on condition [0x00007f4a753d4000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007a143f230> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:1732)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1330)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1198)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4619)

所有的請求都被druid的獲取連線操作阻塞了，最後看原始碼如下