java testwhileidle_DBCP踩坑（二）：连接池检查testWhileIdle失效
問題描述：
生產報錯，“數據庫操作異常”，日志錯誤信息如下：
com.MySQL.jdbc.CommunicationsException: The last packet successfully received from the server was58129 seconds ago.The last packet sent successfully to the server was 58129 seconds ago, which is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
現場情況及觀測現象：mysql端發現周五晚上因連接到了8小時，斷開了一部分連接；
周六周日運行正常，無報錯；
周一早上業務高峰期時發現大量上述報錯；
應用配置了testWhileIdle具體配置是minIdle=125,testWhileIdle=true,validationQuery=SELECT 1,numTestsPerEvictionRun=10,minEvictableEvictionTimeMillis=180000,timeBetweenEvictionMillis=30000
初步分析：從報錯信息上看，是因為數據庫使用到了超過8小時沒有使用過的連接導致,可明明配置了testWhileIdle,理論上不應該有問題，只能分析代源碼了。
源碼分析：
DBCP在初始化參數的時候就會啟動一個檢查線程public synchronized void setTimeBetweenEvictionRunsMillis(long timeBetweenEvictionRunsMillis) {
_timeBetweenEvictionRunsMillis = timeBetweenEvictionRunsMillis;
startEvictor(_timeBetweenEvictionRunsMillis);
}
protected synchronized void startEvictor(long delay) {
if(null != _evictor) {
EvictionTimer.cancel(_evictor);
_evictor = null;
}
if(delay > 0) {
_evictor = new Evictor();
EvictionTimer.schedule(_evictor, delay, delay);
}
}
public void run() {
try {
// 逐出邏輯(包含了validate邏輯)
evict();
} catch(Exception e) {
// ignored
} catch(OutOfMemoryError oome) {
// Log problem but give evictor thread a chance to continue in
// case error is recoverable
oome.printStackTrace(System.err);
}
try {
// 逐出之后，確保池子中連接數滿足最小連接數
ensureMinIdle();
} catch(Exception e) {
// ignored
}
}
復制代碼
每隔30秒執行一次，檢查的邏輯是：public void evict() throws Exception {
assertOpen();
synchronized (this) {
if(_pool.isEmpty()) {
return;
}
if (null == _evictionCursor) {
// 為pool建立一個游標，從尾部到頭遍歷
_evictionCursor = _pool.cursor(_lifo ? _pool.size() : 0);
}
}
//每次檢查numTestsPerEvictionRun個連接
for (int i=0,m=getNumTests();i
final ObjectTimestampPair pair;
synchronized (this) {
if ((_lifo && !_evictionCursor.hasPrevious()) ||
!_lifo && !_evictionCursor.hasNext()) {
// 當游標走到頭部，重新從尾部循環遍歷
_evictionCursor.close();
_evictionCursor = _pool.cursor(_lifo ? _pool.size() : 0);
}
pair = _lifo ?
_evictionCursor.previous() :
_evictionCursor.next();
//將連接取出
_evictionCursor.remove();
_numInternalProcessing++;
}
boolean removeObject = false;
final long idleTimeMilis = System.currentTimeMillis() - pair.tstamp;
//如果存活時間已經超過MinEvictableIdleTimeMillis則準備移除該鏈接
if ((getMinEvictableIdleTimeMillis() > 0) &&
(idleTimeMilis > getMinEvictableIdleTimeMillis())) {
removeObject = true;
} else if ((getSoftMinEvictableIdleTimeMillis() > 0) &&
(idleTimeMilis > getSoftMinEvictableIdleTimeMillis()) &&
((getNumIdle() + 1)> getMinIdle())) { // +1 accounts for object we are processing
removeObject = true;
}
// 若果開啟testwhileidle并且沒有到達minEvictableIdleTimeMillis，執行test邏輯
if(getTestWhileIdle() && !removeObject) {
boolean active = false;
try {
_factory.activateObject(pair.value);
active = true;
} catch(Exception e) {
removeObject=true;
}
if(active) {
// 執行validationQuery
if(!_factory.validateObject(pair.value)) {
removeObject=true;
} else {
try {
_factory.passivateObject(pair.value);
} catch(Exception e) {
removeObject=true;
}
}
}
}
if (removeObject) {
try {
_factory.destroyObject(pair.value);
} catch(Exception e) {
// ignored
}
}
synchronized (this) {
if(!removeObject) {
//對沒有過期的連接放回隊列
_evictionCursor.add(pair);
if (_lifo) {
// Skip over the element we just added back
_evictionCursor.previous();
}
}
_numInternalProcessing--;
}
}
allocate();
}
復制代碼
OK，梳理一下思路dbcp會按照timeBetweenEvictionMillis啟動一個調度線程，每隔timeBetweenEvictionMillis執行一次，每次檢查numTestsPerEvictionRun個連接；
DBCP的數據庫連接池底層為一個雙向鏈表
當一個數據庫鏈接執行過語句，數據庫端會重置連接時間，即正常情況下一個連接如果被執行SELECT 1后，數據庫的8小時計時會重置
檢查的邏輯基于一個游標從后向前遍歷，且會循環遍歷
對超過minEvictableEvictionTimeMillis的連接執行remove，其他的執行validateQuery
dbcp獲取連接時是從前往后獲取的
感覺....似乎...沒毛病啊，只能自己開腦洞想了
開腦洞
腦洞1：
pool雙向鏈表斷了？因為獲取連接是從前往后遍歷的，但是檢查時從后往前的，假設某個節點的前指針指的出問題了，完全可能用到遍歷不到的節點。
合情合理，但沒有證據首先從代碼入口，我們認為雙向鏈表本身的邏輯是不可能有問題的，多半是因為高并發情況下沒有鎖好，導致的問題，但是經過排查發現代碼中對鏈表進行操作的地方，都加了鎖；
測試環境無意中復現出了這個現象，即從mysql端看到有一些鏈接長期沒有刷新Timeout時間，于是我們dump了當時的堆，找到pool對象，并對其進行人工遍歷，發現竟然是對的上的，從前到后從后到前遍歷的是一樣的。
腦洞1不合情不合理。
腦洞2
有些鏈接跑到了鏈表外，導致這些鏈接沒有被遍歷到，可是周一早上確實又使用到了這個連接，所以這個腦洞不成立。
腦洞3
會不會因為高并發，導致每次執行_evictionCursor.hasPrevious()都有新節點(因為連接歸還和新建都是加到頭部的)，嗯，有可能，合情合理。但是這也太巧了，而且我們是有交易高峰期和低谷的，大半夜的沒那么大并發才對，總歸可以走到頭的。
不過腦洞3也給我們提供了一個思路，我們一直以為游標是可以走到頭的，但是會不會是因為什么情況，游標走不到頭，所以一些鏈接至遍歷了一次呢。
找到問題
借著上面的思路，我們發現了真正的問題所在，文字不太好表達，畫個圖各位自己看吧。
問題解決
找到問題原因，解決就簡單了，將minEvictableEvictionTimeMillis調大一些就好了。
創作挑戰賽新人創作獎勵來咯，堅持創作打卡瓜分現金大獎總結
以上是生活随笔為你收集整理的java testwhileidle_DBCP踩坑（二）：连接池检查testWhileIdle失效的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 求求你阻止我！89.2%的人称手机不在身
- 下一篇： 智能手表变革之作！华为WATCH Ult