解Bug之路 Druid的Bug

筆者很熱衷於解決bug,同時比較擅長(網路/協議)部分，所以經常被喚去解決一些網路io方面的bug。現在就挑乙個案例出來，寫出分析思路，以饗讀者，希望讀者在以後的工作中能夠少踩點坑。

此bug是druid低版本的bug,此bug至少在1.0.12版本就已經修復。

在緊張的新專案開發的日子裡,突然收到線上某系統的大量報警,對應系統的人員發現此系統在某一台機器上dump了大量的error日誌。日誌基本都是:

druid:  getconnectiontimeoutexception

此系統所有用到資料庫的地方都丟擲此異常。於是祭出重啟**，重啟過後，一切okay。然後對應的系統人員開始排查這個問題，一直沒有結果。

過了兩天，又收到此型別的error日誌報警，而且這一次是有兩台系統同時爆出此種錯誤。緊急重啟後，將此問題緊急報到我們這邊處理。鑑於本人有豐富的io處理經驗，當然落到了本人頭上。

此系統是通過druid連線後面的資料庫分庫分表proxy,再由此proxy連線後面的資料庫。示意圖如下所示:

獲取連線超時(getconnectiontimeoutexception)此錯誤的出現，只有兩種可能:

1.業務系統本身druid獲取連線失敗。 2.作為中介軟體的sharding proxy獲取連線失敗。

在這個bug裡面很明顯是druid建立連線失敗，原因如下:

1.此系統有10多台機器，僅僅有兩台出現此種故障。 2.這兩台重啟後一切正常。

如果說這兩台是由於同機房問題出現統一的網路連線異常，那麼並不能解釋重啟後正常這一現象。

於是開始分析為何獲取連線超時,第一步當然是開始尋找原始碼中日誌丟擲異常點。上原始碼:

druidconnectionholder holder;
.......
try 
else 
......
}finally 
if(holder == null) else 
}

可見，這邊獲取到的druidconnectionholder為null,則丟擲異常。

在分析這個問題之前，先得看下druid是如何建立連線的,下面是本人閱讀druid原始碼後畫的示意圖:

可見druid建立連線都是通過乙個專門的執行緒來進行的，此圖省略了大量的原始碼細節。

繼續上原始碼

private druidconnectionholder polllast(long nanos) throws interruptedexception, sqlexception 
...try finally 
......
if (poolingcount == 0) 
waitnanoslocal.set(nanos - estimate);
return null;}}
decrementpoolingcount();
druidconnectionholder last = connections[poolingcount];
connections[poolingcount] = null;
return last;}}

可見，如果觸發條件，estimate<=0,則返回null。

上述原始碼的過程示意圖如下:

由此可見，在獲取連線的時候一直超時，不停的爆getconnectiontimeoutexception異常，明顯是由於建立連線線程出了問題。那到底除了什麼問題呢？由於druid的**比較多，很難定位問題點，於是還從日誌入手。

錯誤資訊量最大的是最初出現錯誤的時間點，這是筆者多年排查錯誤的經驗總結。由於正好有兩台出錯，比較其錯誤的共同點也能對解決問題大有裨益。

當筆者和同事追查錯誤的源頭的時候，在有大量的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() 
private void runinternal() catch(sqlexception ex)
......}}

這邊竟然在for(;;)這個死迴圈中break了！！！，那麼這個執行緒也在break後跳出了死迴圈從而結束了，也就是說建立連線線程被銷毀了！！!如下圖所示:

繼續搜尋日誌,發現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導致頻繁gc(並定位記憶體洩**),導致了上述現象，如下圖所示:

由於每次記憶體洩露過小，同時sharding proxy設定的記憶體過大。所以上線後過了乙個月才有頻繁的gc現象。之前上線後，大家觀察了一周，發現沒有任何異常，就不再關注。與此類似，如果db負載過高的話，筆者推測也會觸發druid的bug。

筆者去翻druid最新原始碼，發現此問題已經修復，緊急聯絡各業務線公升級druid,同時讓sharding proxy負責人修改了最新**並上線。

終於這次的連環bug算是填完了。

追查bug，日誌和原始碼是最重要的兩個部分。最源頭的日誌資訊量最大，同時要對任何不同尋常的現象都加以分析並推測，最後結合原始碼，才能最終找出bug。

解Bug之路 Druid的Bug

解BUG的一些心得

由解乙個bug想到的

合理的製造bug，及查詢bug

解Bug之路 Druid的Bug

解BUG的一些心得

由解乙個bug想到的

合理的製造bug，及查詢bug

相關推薦