2019獨角獸企業(yè)重金招聘Python工程師標準>>>

解Bug之路-Druid的Bug

筆者很熱衷于解決Bug,同時比較擅長(網(wǎng)絡(luò)/協(xié)議)部分，所以經(jīng)常被喚去解決一些網(wǎng)絡(luò)IO方面的Bug?，F(xiàn)在就挑一個案例出來，寫出分析思路，以饗讀者，希望讀者在以后的工作中能夠少踩點坑。

前言

此Bug是Druid低版本的Bug,此Bug至少在1.0.12版本就已經(jīng)修復。

Druid的Bug現(xiàn)場

在緊張的新項目開發(fā)的日子里,突然收到線上某系統(tǒng)的大量報警,對應(yīng)系統(tǒng)的人員發(fā)現(xiàn)此系統(tǒng)在某一臺機器上dump了大量的error日志。日志基本都是:

Druid: GetConnectionTimeoutException

此系統(tǒng)所有用到數(shù)據(jù)庫的地方都拋出此異常。于是祭出重啟大法，重啟過后，一切Okay。然后對應(yīng)的系統(tǒng)人員開始排查這個問題，一直沒有結(jié)果。
過了兩天，又收到此類型的error日志報警，而且這一次是有兩臺系統(tǒng)同時爆出此種錯誤。緊急重啟后，將此問題緊急報到我們這邊處理。鑒于本人有豐富的IO處理經(jīng)驗，當然落到了本人頭上。

Bug復盤

此系統(tǒng)是通過Druid連接后面的數(shù)據(jù)庫分庫分表Proxy,再由此Proxy連接后面的數(shù)據(jù)庫。示意圖如下所示:

縮小Bug范圍

獲取連接超時(GetConnectionTimeoutException)此錯誤的出現(xiàn)，只有兩種可能:

1.業(yè)務(wù)系統(tǒng)本身Druid獲取連接失敗。 2.作為中間件的Sharding Proxy獲取連接失敗。

在這個Bug里面很明顯是Druid創(chuàng)建連接失敗，原因如下:

1.此系統(tǒng)有10多臺機器，僅僅有兩臺出現(xiàn)此種故障。 2.這兩臺重啟后一切正常。

如果說這兩臺是由于同機房問題出現(xiàn)統(tǒng)一的網(wǎng)絡(luò)連接異常，那么并不能解釋重啟后正常這一現(xiàn)象。

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是如何創(chuàng)建連接的,下面是本人閱讀Druid源碼后畫的示意圖:

可見druid創(chuàng)建連接都是通過一個專門的線程來進行的，此圖省略了大量的源碼細節(jié)。

為何Holde為null?

繼續(xù)上源碼

private DruidConnectionHolder pollLast(long nanos) throws InterruptedException, SQLException {for (;;) {if (poolingCount == 0) {emptySignal(); // send signal to CreateThread create connectionif (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;} }

可見，如果觸發(fā)條件，estimate<=0,則返回null。
上述源碼的過程示意圖如下:

繼續(xù)追蹤

由此可見，在獲取連接的時候一直超時，不停的爆GetConnectionTimeoutException異常，明顯是由于創(chuàng)建連接線程出了問題。那到底除了什么問題呢？由于Druid的代碼比較多，很難定位問題點，于是還從日志入手。

進一步挖掘日志

錯誤信息量最大的是最初出現(xiàn)錯誤的時間點，這是筆者多年排查錯誤的經(jīng)驗總結(jié)。由于正好有兩臺出錯，比較其錯誤的共同點也能對解決問題大有裨益。

大量create connection error

當筆者和同事追查錯誤的源頭的時候，在有大量的create connection error,奇怪的是，到了一個時間點之后，就只剩GetConnectionTimeoutException異常了。
繼續(xù)分析，在出現(xiàn)create connection error的時候，還是有部分業(yè)務(wù)請求能夠執(zhí)行的。即獲取到了連接。
翻了翻源碼，create connection error是在創(chuàng)建連接線程打印的，如果這個異常沒有繼續(xù)打印，而同時連接也獲取不到，就在很大程度上表明:

創(chuàng)建連接根本就是被銷毀了！

錯誤分界點

于是開始尋找什么時候create connection error開始銷毀。于是通過筆者和同事在無數(shù)的錯誤日志中用肉眼發(fā)現(xiàn)了一個不尋常的日志隱蔽在大量的錯誤日志間:

Druid:create holder error

在這個錯誤出現(xiàn)之后，就再也沒有了create connection error,翻了翻另一臺機器的日志，頁是同樣的現(xiàn)象！

源碼尋找Bug

隱隱就感覺這個日志是問題錯誤的關(guān)鍵，打出這個日志的源碼為:

創(chuàng)建連接線程 @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(;;)這個死循環(huán)中break了！！！，那么這個線程也在break后跳出了死循環(huán)從而結(jié)束了，也就是說創(chuàng)建連接線程被銷毀了！！!如下圖所示:

為何create holder error?

繼續(xù)搜尋日志,發(fā)現(xiàn)create holder error之前，會有獲取事務(wù)隔離級別的報錯。那么結(jié)合源碼，錯誤的發(fā)生如下圖:

即在Druid的創(chuàng)建連接線程創(chuàng)建連接成功之后，還需要拿去數(shù)據(jù)庫的holdability,isolation(隔離級別)等MetaData,在獲取MetaData失敗的時候，則會拋出異常，導致創(chuàng)建連接線程Break。
但是如果在handshake的時候就失敗，那么由于Druid處理了這種異常，打印create connection error,并繼續(xù)創(chuàng)建連接。
于是就有了在create holder error之前大量create connection error，在這之后沒有了的現(xiàn)象。

完結(jié)了么？

Druid的Bug是弄清楚了，但是為何連接如此不穩(wěn)定，有大量的創(chuàng)建連接異常，甚至于Druid前腳創(chuàng)建連接成功，后腳發(fā)送命令就失敗呢？

Sharding Proxy的Bug

于是此問題又縈繞在筆者心頭，在又一番不下于上述過程的努力之后，發(fā)現(xiàn)一個月之前上線的新版本的Sharding Proxy的內(nèi)存泄露Bug導致頻繁GC(并定位內(nèi)存泄露點),導致了上述現(xiàn)象，如下圖所示:

由于每次內(nèi)存泄露過小，同時Sharding Proxy設(shè)置的內(nèi)存過大。所以上線后過了一個月才有頻繁的GC現(xiàn)象。之前上線后，大家觀察了一周，發(fā)現(xiàn)沒有任何異常，就不再關(guān)注。與此類似，如果DB負載過高的話，筆者推測也會觸發(fā)Druid的Bug。

最后處理

筆者去翻Druid最新源碼，發(fā)現(xiàn)此問題已經(jīng)修復，緊急聯(lián)系各業(yè)務(wù)線升級Druid,同時讓Sharding Proxy負責人修改了最新代碼并上線。
終于這次的連環(huán)Bug算是填完了。

總結(jié)

追查Bug，日志和源碼是最重要的兩個部分。最源頭的日志信息量最大，同時要對任何不同尋常的現(xiàn)象都加以分析并推測，最后結(jié)合源碼，才能最終找出Bug。

原文鏈接

https://my.oschina.net/alchemystar/blog/899987

轉(zhuǎn)載于:https://my.oschina.net/alchemystar/blog/899987

總結(jié)

以上是生活随笔為你收集整理的解Bug之路-Druid的Bug的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。