解Bug之路-Druid的Bug
筆者很熱衷于解決Bug,同時比較擅長(網絡/協議)部分，所以經常被喚去解決一些網絡IO方面的Bug。現在就挑一個案例出來，寫出分析思路，以饗讀者，希望讀者在以后的工作中能夠少踩點坑。
前言
此Bug是Druid低版本的Bug,此Bug至少在1.0.12版本就已經修復。
Druid的Bug現場
在緊張的新項目開發的日子里,突然收到線上某系統的大量報警,對應系統的人員發現此系統在某一臺機器上dump了大量的error日志。日志基本都是:
Druid: GetConnectionTimeoutException
此系統所有用到數據庫的地方都拋出此異常。于是祭出重啟大法，重啟過后，一切Okay。然后對應的系統人員開始排查這個問題，一直沒有結果。
過了兩天，又收到此類型的error日志報警，而且這一次是有兩臺系統同時爆出此種錯誤。緊急重啟后，將此問題緊急報到我們這邊處理。鑒于本人有豐富的IO處理經驗，當然落到了本人頭上。
Bug復盤
此系統是通過Druid連接后面的數據庫分庫分表Proxy,再由此Proxy連接后面的數據庫。示意圖如下所示:
縮小Bug范圍
獲取連接超時(GetConnectionTimeoutException)此錯誤的出現，只有兩種可能:
1.業務系統本身Druid獲取連接失敗。
2.作為中間件的Sharding Proxy獲取連接失敗。
在這個Bug里面很明顯是Druid創建連接失敗，原因如下:
1.此系統有10多臺機器，僅僅有兩臺出現此種故障。
2.這兩臺重啟后一切正常。
如果說這兩臺是由于同機房問題出現統一的網絡連接異常，那么并不能解釋重啟后正常這一現象。
Druid問題定位
于是開始分析為何獲取連接超時,第一步當然是開始尋找源碼中日志拋出異常點。上源碼:
DruidConnectionHolder holder;
.......
try {
if (maxWait > 0) {
holder = pollLast(nanos);
}
else {
holder = takeLast();
}
......
}finally {
lock.unlock();
}
if(holder == null){
......
if (this.createError != null) {
throw new GetConnectionTimeoutException(errorMessage, createError);
} else {
throw new GetConnectionTimeoutException(errorMessage);
}
}
可見，這邊獲取到的DruidConnectionHolder為null,則拋出異常。
Druid獲取連接的過程
在分析這個問題之前，先得看下Druid是如何創建連接的,下面是本人閱讀Druid源碼后畫的示意圖:
可見druid創建連接都是通過一個專門的線程來進行的，此圖省略了大量的源碼細節。
為何Holde為null?
繼續上源碼
private DruidConnectionHolder pollLast(long nanos) throws InterruptedException, SQLException {
for (;;) {
if (poolingCount == 0) {
emptySignal(); // send signal to CreateThread create connection
if (estimate <= 0) {
waitNanosLocal.set(nanos - estimate);
return null;
}
...
try {
long startEstimate = estimate;
estimate = notEmpty.awaitNanos(estimate);
......
} finally {
......
}
......
if (poolingCount == 0) {
if (estimate > 0) {
continue;
}
waitNanosLocal.set(nanos - estimate);
return null;
}
}
decrementPoolingCount();
DruidConnectionHolder last = connections[poolingCount];
connections[poolingCount] = null;
return last;
}
}
可見，如果觸發條件，estimate<=0,則返回null。
上述源碼的過程示意圖如下:
繼續追蹤
由此可見，在獲取連接的時候一直超時，不停的爆GetConnectionTimeoutException異常，明顯是由于創建連接線程出了問題。那到底除了什么問題呢？由于Druid的代碼比較多，很難定位問題點，于是還從日志入手。
進一步挖掘日志
錯誤信息量最大的是最初出現錯誤的時間點，這是筆者多年排查錯誤的經驗總結。由于正好有兩臺出錯，比較其錯誤的共同點也能對解決問題大有裨益。
大量create connection error
當筆者和同事追查錯誤的源頭的時候，在有大量的create connection error,奇怪的是，到了一個時間點之后，就只剩GetConnectionTimeoutException異常了。
繼續分析，在出現create connection error的時候，還是有部分業務請求能夠執行的。即獲取到了連接。
翻了翻源碼，create connection error是在創建連接線程打印的，如果這個異常沒有繼續打印，而同時連接也獲取不到，就在很大程度上表明:
創建連接根本就是被銷毀了！
錯誤分界點
于是開始尋找什么時候create connection error開始銷毀。于是通過筆者和同事在無數的錯誤日志中用肉眼發現了一個不尋常的日志隱蔽在大量的錯誤日志間:
Druid:create holder error
在這個錯誤出現之后，就再也沒有了create connection error,翻了翻另一臺機器的日志，頁是同樣的現象！
源碼尋找Bug
隱隱就感覺這個日志是問題錯誤的關鍵，打出這個日志的源碼為:
創建連接線程
@Override
public void run() {
runInternal();
}
private void runInternal() {
for (; ; ) {
......
try{
holder = new DruidConnectionHolder(DruidDataSource.this,connection);
}catch(SQLException ex){
LOG.error("create connection holder error",ex);
// 這句break就是罪魁禍首
// 至少在1.0.12修復
break;
}
......
}
}
這邊竟然在for(;;)這個死循環中break了！！！，那么這個線程也在break后跳出了死循環從而結束了，也就是說創建連接線程被銷毀了！！!如下圖所示:
為何create holder error?
繼續搜尋日志,發現create holder error之前，會有獲取事務隔離級別的報錯。那么結合源碼，錯誤的發生如下圖:
即在Druid的創建連接線程創建連接成功之后，還需要拿去數據庫的holdability,isolation(隔離級別)等MetaData,在獲取MetaData失敗的時候，則會拋出異常，導致創建連接線程Break。
但是如果在handshake的時候就失敗，那么由于Druid處理了這種異常，打印create connection error,并繼續創建連接。
于是就有了在create holder error之前大量create connection error，在這之后沒有了的現象。
完結了么？
Druid的Bug是弄清楚了，但是為何連接如此不穩定，有大量的創建連接異常，甚至于Druid前腳創建連接成功，后腳發送命令就失敗呢？
Sharding Proxy的Bug
于是此問題又縈繞在筆者心頭，在又一番不下于上述過程的努力之后，發現一個月之前上線的新版本的Sharding Proxy的內存泄露Bug導致頻繁GC(并定位內存泄露點),導致了上述現象，如下圖所示:
由于每次內存泄露過小，同時Sharding Proxy設置的內存過大。所以上線后過了一個月才有頻繁的GC現象。之前上線后，大家觀察了一周，發現沒有任何異常，就不再關注。與此類似，如果DB負載過高的話，筆者推測也會觸發Druid的Bug。
最后處理
筆者去翻Druid最新源碼，發現此問題已經修復，緊急聯系各業務線升級Druid,同時讓Sharding Proxy負責人修改了最新代碼并上線。
終于這次的連環Bug算是填完了。
總結 追查Bug，日志和源碼是最重要的兩個部分。最源頭的日志信息量最大，同時要對任何不同尋常的現象都加以分析并推測，最后結合源碼，才能最終找出Bug。
來自：http://www.iteye.com/news/32414