解Bug之路-Druid的Bug
來自專欄我是程序員
14 人贊了文章
解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
隱隱就感覺這個日誌是問題錯誤的關鍵，打出這個日誌的源碼為:
創建連接線程@Overridepublic 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之前，會有獲取事務隔離級別的報錯。那麼結合源碼，錯誤的發生如下圖:
於是就有了在create holder error之前大量create connection error，在這之後沒有了的現象。
完結了么？
Druid的Bug是弄清楚了，但是為何連接如此不穩定，有大量的創建連接異常，甚至於Druid前腳創建連接成功，後腳發送命令就失敗呢？
Sharding Proxy的Bug
於是此問題又縈繞在筆者心頭，在又一番不下於上述過程的努力之後，發現一個月之前上線的新版本的Sharding Proxy的內存泄露Bug導致頻繁GC(並定位內存泄露點),導致了上述現象，如下圖所示:
最後處理
筆者去翻Druid最新源碼，發現此問題已經修復，緊急聯繫各業務線升級Druid,同時讓Sharding Proxy負責人修改了最新代碼並上線。
終於這次的連環Bug算是填完了。總結
追查Bug，日誌和源碼是最重要的兩個部分。最源頭的日誌信息量最大，同時要對任何不同尋常的現象都加以分析並推測，最後結合源碼，才能最終找出Bug。
本文作者：無毀的湖光
原文鏈接
更多技術乾貨敬請關注云棲社區知乎機構號：阿里云云棲社區 - 知乎
本文為雲棲社區原創內容，未經允許不得轉載。
推薦閱讀：