DAS解決訪問數據庫延時突高的案例分享

1、前言

一、DAS介紹

DAS是信也科技自研的數據庫訪問框架。它包括數據庫控制檯das console，數據庫客戶端das client和數據庫服務端das server三部分。DAS是基於Java語言開發的，支持數據庫管理，ORM，SQL建立，分庫分表操做的一體化數據庫訪問解決方案。DAS項目從去年開始已經在GitHub上開源：https://github.com/ppdaicorp/das

DAS直連方式架構圖：

信也科技的應用大量使用DAS做爲數據庫訪問中間件，目前幾百個應用接入了DAS。

做爲公司的標準數據庫訪問技術，DAS上線以來一直運行穩定。做爲DAS團隊，咱們在接入的衆多應用實戰中積累了很多數據庫訪問相關的經驗。
雖然咱們這裏分享的是DAS的真實技術支持的案例，可是我認爲它的通過和結果對相似的情景仍舊頗有借鑑的意義。

二、問題背景

去年公司有一個使用了DAS的對接外部系統的應用，應用開發人員反映系統會時不時地發生數據庫慢查詢。咱們經過日誌系統發現這些慢查詢發生的比率極低，甚至低於千分之一。

若是這是個普通的應用，低於千分之一的慢查詢比率是能夠接受的。可是這一個對接外部系統的應用，外部系統對延時要求很是高，即便千分之一的高延遲仍舊不知足需求。

三、問題定位

首先，咱們聯繫了DBA，從數據庫日誌角度查看是數據庫端是否有慢查詢發生。DBA團隊在MySQL上面有專門記錄慢查詢的日誌。慢查詢的日誌結果是否認的，並且數據庫的數據量也在合理的水平。若是數據庫端沒有發生慢查詢，那必定是整個鏈路其餘地方發生了延時，隨後咱們把精力回到應用端。

經過研究日誌，咱們發現了和直覺相反的現象：延時沒有發生在數據庫操做頻率比較高的操做上，而是發生在一些操做頻率很低的操做上。

問題極可能和程序狀態變遷有關。在應用端，DAS自己是一個無狀態的架構，它主要依賴於無狀態的JDBC和DataSource。DataSource是典型有狀態的程序，因此問題發生在DataSource的可能性最大。

DataSource的本質是爲了節省程序的時間和空間，對數據庫鏈接作的緩存。它的設計思路和其餘軟件緩存的設計思路是同樣的：要把實例放到緩存池管理，只不過這裏的實例是數據庫鏈接。每種數據庫緩存池都有一系列的配置參數，它們都是用來調節緩存池的行爲，經過不一樣的參數配置就能爲不一樣的場景服務。

經過分析DataSource的配置，咱們找到了緣由。緣由是因爲數據庫數據庫兩次操做間隔空閒時間太長，致使鏈接池裏全部的idle鏈接被清空。後續新鏈接須要創建物理鏈接，每次創建物理鏈接，須要創建socket以及數據庫的安全認證這些費時操做。

既然問題定位在DataSource對idle鏈接的行爲上，那麼咱們就從idle的配置着手。DAS使用Tomcat的DataSource獲取數據庫鏈接實例。Tomcat的數據源提供了有不少的配置參數，這些參數決定了數據源的行爲。
咱們最後把參數定位在minIdle這個參數上。從Tomcat官方文檔上這樣解釋這個參數：

The minimum number of established connections that should be kept in the pool at all times.

若是把數據源看作一個緩存，那麼minIdle就是這個緩存的minimum pool size。當時咱們這個minIdle參數設置的是0，設置成0的目的在於節省數據庫鏈接。數據庫鏈接是一種寶貴的資源，一個程序保持idle的鏈接太多不釋放是一種浪費，對數據庫這個共享的資源更是浪費，一個數據庫每每同時被多個應用共同使用。
DBA會設置每一個數據庫的最大鏈接數（max_connections）用以保護數據庫不被請求壓垮。當一個應用佔據過多idle的鏈接，勢必會影響其餘應用的鏈接獲取。

當minIdle參數設置成0，當然節約鏈接，可是它在極端狀況下可能產生效果就是：當鏈接池中的鏈接長久不用時，鏈接池內全部idle鏈接所有被清空。Tomcat數據源會在後臺定時啓一個線程清理idle的鏈接，將idle的鏈接數降到minIdle。
在設置成0以後，至關於鏈接池會被清空，因而後續第一個鏈接就須要創建真正的物理數據庫鏈接，致使耗時飆高。在這個案例中，就是發生了這個狀況。

2、解決過程

一、初步嘗試

咱們將參數minIdle從0改成1，這樣一來鏈接池中至少有一個鏈接能夠被複用，並且保持一個idle鏈接也不算浪費。同時，咱們經過增大了minEvictableIdleTimeMillis的參數把鏈接池中idle鏈接的最小空閒時間從30秒增大到10分鐘。這樣的話，位於緩存池裏的idle鏈接生命週期延長了，池子裏的idle數變多，增長了緩存命中率。須要注意的是minEvictableIdleTimeMillis這個參數控制的是evict掉緩存池裏大於minIdle數的鏈接，在minIdle範圍裏面的鏈接是不會被它evict的。

是否是完美解決問題？不，故事未完。

二、遇到新問題

當咱們在測試的時候發現，程序會報異常：

Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
The last packet successfully received from the server was 9,969,393 milliseconds ago.

這是由minIdle設置爲1形成的。經過調查發現，這是因爲MySQL服務器有一個wait_timeout的參數，默認是8小時。這也是一個保護MySQL數據庫自我節省資源的行爲。咱們的數據庫設置的30分鐘，是也就是說一個鏈接空閒超過30分鐘，MySQL服務器將主動斷開該鏈接。例子中的9,969,393毫秒至關於好幾個小時，遠超30分鐘，因此致使了這種異常。這時應用從DataSource取鏈接的話，取到的就是那個失效的鏈接。minIdle設置成1之後，那個長時間idle的鏈接就一直呆在鏈接池裏面，甚至被MySQL服務器端斷掉。

那加大wait_timeout？加大wait_timeout是不符合DBA規範。怎麼辦？Tomcat數據源提供了另外一個有用的參數testOnBorrow，官方文檔上這樣解釋這個參數：

The indication of whether objects will be validated before being borrowed from the pool.
If the object fails to validate, it will be dropped from the pool, and we will attempt to borrow another.

若是把這個默認false值變爲true以後，鏈接池會把鏈接從鏈接池拿出的時候會作驗證鏈接有效性。這樣就保證了從池裏出來都是有效的鏈接。

三、驗證與上線

最後，咱們在本地開發環境驗證瞭解決這個鏈接超時的方案。首先，先把本地測試MySQL服務器的wait_timeout的參數調低便於模擬超時，而後經過代碼邏輯控制，將兩次訪問數據庫的時間間隔超過wait_timeout參數時間，觀察數據源在這種場景下的表現。在兩個不一樣的數據源配置測試條件下，觀察兩次程序的結果。

本地驗證成功以後，爲了不修改配置以後引起新的問題，咱們首先進行了JUnit單元迴歸測試，保證基本功能完整。經過這幾百個JUnit單元測試以後，把新配置部署到正式的測試環境進行觀察。確認測試環境運行正常之後，最後才把配置更新到預發和生產環境。正規完善的流程是軟件質量的保證。

至此，完美解決了這個問題。

四、其餘數據源的應對

有人會問若是我沒用Tomcat的數據源，用的是其餘的數據源實現該如何作呢？
對於一個成熟的數據源產品來講，Idle connection handling和Validation都是必有的功能。市面上大部分主流的數據源產品都有這些相似的參數。
譬如說流行的Druid和DBCP2，他們也都有如出一轍的minIdle，minEvictableIdleTimeMillis和testOnBorrow配置項。HikariCP的相似配置項是minimumIdle和idleTimeout。

3、感悟與總結

解決這個延時突高的問題，只是咱們中間件團隊衆多平常技術支持的一個案例。

咱們中間件團隊和其餘技術團隊相比有特別之處，在於須要服務於公司各類不一樣的業務線和技術線。咱們的用戶有着不一樣的需求和特性，應用場景不一樣，技術要求也不一樣，也就會產生各類各樣的問題。有對併發要求高的，有對延時要求高的，有對API易用性要求高的，有對監控數據要求高的，等等。

雖然遇到故障和問題各色各樣，可是咱們仍是從這些實戰中總結出一些共性的地方。咱們能夠把解決問題的過程總結爲：反覆地假設問題和論證，最後定位解決問題的過程。拿這個案例來講，起初用戶來找到咱們報問題的時候，咱們也一頭霧水：爲啥低併發的延時比高併發還高？起初，由於沒有明確的懷疑點，因此咱們將鏈路上的每一點都檢查了一下。從數據庫到網絡，甚至諮詢了作監控的同窗，以確認延時時間的正確性。經過反覆調查，咱們纔將問題定位在客戶端。

在排查問題的過程當中，好的監控起到了關鍵做用。通常監控有兩類輸出：警告和日誌。應用團隊就是經過警告及時發現了問題，而咱們中間件團隊利用日誌排查問題。日誌的質量每每決定了定位問題的效率。好的監控可以提升你從表面現象到找到背後緣由（從what到why）的效率。

在這個解決這個延時突高的案例上，咱們也是從日誌上獲得蛛絲馬跡。DAS自己會打詳細的日誌，經過這些日誌，咱們能夠看到DAS的代碼和它底層JDBC消耗的時間，從而定位耗時發生在DAS的更底層。咱們還有個集中式日誌系統，能在上面看到異常日誌的原始信息，也能夠在這個系統上面看各類維度的統計數據，譬如說，對這個案例相當重要的999線和QPS。若是咱們沒有這些信息，我懷疑還能不能定位這個問題。

但願咱們的此次排查問題的經歷通過對你們有所幫助！

最後，請掏出你的手機：

---

做者介紹

Shengyuan，信也科技佈道師、框架中間件資深專家、目前主要從事DAS相關的研發、運維工做。