Categories
程式開發

DAS 解決延時突高的案例分享


DAS是信也科技自研的數據庫訪問框架。它包括數據庫控制台das console,數據庫客戶端das client和數據庫服務端das server三部分。 DAS是基於Java語言開發的,支持數據庫管理,ORM,SQL創建,分庫分錶操作的一體化數據庫訪問解決方案。

DAS項目從去年開始已經在GitHub上開源:https://github.com/ppdaicorp/das

DAS 解決延時突高的案例分享 1

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之後,相當於連接池會被清空,於是後續第一個連接就需要建立真正的物理數據庫連接,導致耗時飆高。在這個案例中,就是發生了這個情況。

解決方案

我們將參數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。

感悟與總結

解決這個延時突高的問題,只是我們中間件團隊眾多日常技術支持的一個案例。

我們中間件團隊和其他技術團隊相比有特別之處,在於需要服務於公司各種不同的業務線和技術線。我們的用戶有著不同的需求和特性,應用場景不同,技術要求也不同,也就會產生各種各樣的問題。有對並發要求高的,有對延時要求高的,有對API易用性要求高的,有對監控數據要求高的,等等。

雖然遇到故障和問題各色各樣,但是我們還是從這些實戰中總結出一些共性的地方。我們可以把解決問題的過程總結為:反复地假設問題和論證,最後定位解決問題的過程。拿這個案例來說,起初用戶來找到我們報問題的時候,我們也一頭霧水:為啥低並發的延時比高並發還高?起初,因為沒有明確的懷疑點,所以我們將鏈路上的每一點都檢查了一下。從數據庫到網絡,甚至諮詢了做監控的同學,以確認延時時間的正確性。通過反複調查,我們才將問題定位在客戶端。

在排查問題的過程中,好的監控起到了關鍵作用。一般監控有兩類輸出:警告和日誌。應用團隊就是通過警告及時發現了問題,而我們中間件團隊利用日誌排查問題。日誌的質量往往決定了定位問題的效率。好的監控能夠提高你從表面現像到找到背後原因(從what到why)的效率。

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

希望我們的這次排查問題的經歷經過對大家有所幫助!