JDBC驅動自身問題引起的FullGC

 

公衆號HelloJava刊出一篇《MySQL Statement cancellation timer 故障排查分享》，做者的某服務的線上機器報 502（502是 nginx 作後端健康檢查時不能鏈接到 server 時拋出的提示），他用 jstack -l 打印線程堆棧，發現了大量可疑的「MySQL Statementcancellation timer」，進一步探究緣由，原來是業務應用將數據庫更新操做和雲存儲傳圖操做放在同一個事務。當雲存儲發生異常時，因爲缺乏雲存儲操做的快速失敗，而且缺乏對總體事務的超時控制，致使整個應用被夯住，進而 502。

做者文中還談及他排查過程當中注意到 MySQL-Connector-Java 的一個 bug，在 5.1.27 版本之前 MySQL Statement cancellation timer 會致使 Perm 區 Leak，內存泄漏後進而業務應用異常。

咱們恰巧遇到過這個坑。鑑於這個坑的排查過程和測試驗證還挺有趣，我貼一下去年咱們的 RCA 報告：

 

RCA：JDBC驅動自身問題引起的FullGC

鄭昀 基於田志全和端木洪濤的分析報告 2015/6/30

關鍵詞：Java，JDBC，升級，MySQL驅動，頻繁數據查詢，mysql-5.1.34，mysql-5.0.7

 

問題現象：

    2015年4月22日（週日）晚間，線上 TaskMall 工程（一個 Java 工程）頻繁報警。分析 jvm 狀況，taskmall 在內存使用上確實存在問題，可能有大量對象不正常堆積：

圖2 155 jmap

 

問題緣由：

  頻繁的大數據查詢場景下，mysql-5.1.34 驅動的性能遠優於 mysql-5.0.7 驅動。必定要及時升級驅動啊。

RCA類型：

  維護問題。

  其實咱們在RCA(Root Cause Analysis)第四季就曾經遇到此類問題：

第四季案例5 官方驅動也會設計不當，及時升級 ——實例： 2013年1月，因爲 PHP 一直使用 MongoDB PHP Driver 1.2.x 驅動，致使 PHP-FPM 模式下，每個 PHP Worker 進程都有本身獨立的 mongodb 鏈接池，從而致使鏈接數極易超標，佔用內存數也隨之倍增，MongoDB 負載很重。 如當時編輯後臺192 --> mongodb-165 之間的鏈接數基本維持在：750～751個左右。 升級到 mongodb-php driver 1.3.2 驅動以後，平常鏈接數大爲降低。 ——教訓： 引入了重要存儲介質的驅動以後，如spymemcahced、mongodb php/java driver、jedis等，保持跟蹤它們的動態，第一時間更新驅動。

問題分析：

  志全分析堆棧信息發現，系統中有大量的 CancelTask 定時任務須要執行。

圖3 大量的CancelTask

 

  爲何會有這麼多的任務呢？

  這是 mysql 的一個定時任務，主要用於查詢超時處理。即，系統在執行一個 sql 查詢時，jdbc 會給你一個超時時間。爲了保證超時時間後，可以關閉 statement，會打開一個保護關閉的定時任務。若是超時狀況下，sql 還沒響應執行，cancel task 就會執行關閉任務。注，ibatis 的默認超時時間爲3秒（<setting name="defaultStatementTimeout" value="3000" />）。

圖4 mysql源碼

  其實，cancel() 方法只是對狀態作了一個標記而已：

圖5 mysql源碼

  只有在調度任務時，發現狀態爲取消，纔會真正移除該任務：

圖6 mysql源碼

因而，在某些狀況下，CancelTask 會大量累積，從而嚴重影響 JVM 內存，最終引起 FullGC！

 

問題解決：

  志全分析了 MySQL 最新的 jdbc 驅動，發現 CancelTask 在 mysql 驅動中，後續的版本已經不採用全局的 Timer 任務池了。

在 mysql-connector-java-5.0.7-bin.jar 中：

圖7 mysql源碼

 

而在 mysql-connector-java-5.1.34-bin.jar 中：

圖8 mysql源碼

 

  端木洪濤通過針對性的壓力測試，確實證明了這個現象能夠重現。測試報告以下所示：

測試時間：2015年4月29日 使用taskmall聯調環境作測試。 協調器：10.8.210.168 分發器：10.9.210.15一、10.9.210.152 執行器：10.9.210.154   分發器配置以下： 151使用mysql-5.1.34驅動，152使用mysql-5.0.7驅動。其中分發器兩機器爲2核8G配置，統一resin4 JVM配置：                <jvm-arg>-Xmx1024M</jvm-arg>                <jvm-arg>-Xms1024M</jvm-arg>                <jvm-arg>-Xmn512M</jvm-arg>                <jvm-arg>-XX:SurvivorRatio=6</jvm-arg>                <jvm-arg>-Xss1024k</jvm-arg>                <jvm-arg>-XX:PermSize=256M</jvm-arg>                <jvm-arg>-XX:MaxPermSize=256M</jvm-arg>   基礎準備： 一、往數據庫中壓入5180條隊列數據，（其中151機器分的2614條，152機器分得2566條）； 二、改造執行器，使其只接受數據不處理數據。則5180條數據對分發器來講一直都是有效數據； 三、改造分發器，設置ibatis參數：cacheModelsEnabled="true"、defaultStatementTimeout="3000"。每150ms加載一次數據；     （分發器起16個線程對應16個cobar分庫，每一個線程分頁加載分庫中的有效數據，每頁200條數據。） 四、jvisualvm遠程監控15一、152機器。   測試結果以下： 1、15分鐘後監控結果以下 從圖上看出152機器從cpu佔用、堆大小在逐漸升高，查看gc日誌發現152已經開始出現FullGC。   152機器已快掛：   151機器則一切正常：   2、32分鐘後監控結果以下 此時除了cpu佔用、堆飆高外，152的線程數也遠遠高於151。此時的152已經頻繁FullGC了。 152機器：   151機器則：   統計堆內存中活着對象數據： 152機器出現大量的Byte數據以及PreparedStatement，以及CancelTask。 1）可是在151機器上前47位的佔用排行上找不到CancelTask。 2）在byte數據量上，152機器達到了600M，而151機器只有幾十M。   測試結論： 頻繁的大數據查詢場景下，mysql-5.1.34 驅動的性能處理遠優於 mysql-5.0.7 驅動。

 

-EOF-

歡迎訂閱個人微信訂閱號『老兵筆記』，請掃描二維碼關注：