基於TBDS的flume異常問題排查過程

版權聲明：本文由王亮原創文章，轉載請註明出處: 
文章原文連接：https://www.qcloud.com/community/article/214

來源：騰雲閣 https://www.qcloud.com/community

 

現象

長期運營中發現部署了flume集羣的磁盤滿，通過排查發現flume的日誌目錄致使。

具體問題

具體看flume的大文件日誌發現，某個MySQL相關的sink持續拋出異常，打印了大量的日誌

分析過程

根據這個異常信息（exception）即：
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed
字面意思爲MySQL服務的狀態（鏈接）已經關閉的狀態下，仍然有提交事務操做，拋出了異常，但這個異常持續拋出，仍須要深刻分析。

配置分析

既然是flume拋出的，且與MySQL有關，那縮小問題範圍，查找flume裏誰在寫MySQL。（flume的配置通常位於/etc/flume/conf/agent/flume.conf）

根據配置中惟一一條與MySQL相關的配置邏輯：讀取HiveServer的日誌，過濾其中的SQL語句（以Metadata collec*過濾），結果存入到sink裏配置的MySQL數據表hive_run_sqlinfo。

flumeagent邏輯分析

以上sink裏調用了一個com.tencent.tbds.flume.sink.MysqlSinkForMetadata的類，這是一個自定義類，咱們在引用路徑裏找到這個類所在jar並反編譯之（decompiler），基本邏輯與註釋以下：

Sink初始化階段

Sink循環執行階段

Sink關閉階段

關閉階段僅僅檢查鏈接是否存在。

可能的緣由

從sink的邏輯看，只有在空鏈接的狀況下，sink狀態纔會是BACKOFF，其餘狀況下狀態都是READY，且在向MySQL提交事務先後，不會檢查鏈接狀態，即便在SQL拋出異常的狀況下也沒有修改sink狀態，致使提交拋出異常後，sink循環執行，循環拋出異常。這裏就是不斷拋出異常的根本。那麼鏈接究竟是何時關閉的呢？這裏的緣由猜想有2個：(1)sink長時間與MySQL沒有交互，超過鏈接自動關閉時間；(2)MySQL的異常關閉。

問題確認

是否sink長時間與MySQL無交互
查詢MySQL的超時配置以下：

配置爲默認配置28800秒即8小時。
查看HiveServer的日誌，統計每小時執行SQL的數量以下：

可見，sink與MySQL之間的斷開並不是兩者長期無交互。

是否人爲斷開服務
查詢人爲啓動MySQL的時間以下：

flume的異常時間以下：（從異常提交的事務自己內容的時間看）：

時間吻合。

結論
MySQL服務異常致使flume提交事務時鏈接中斷，且flume沒有處理這種異常，引起死循環提交事務，並在這種異常狀況下，flume已沒法正常工做。

問題重現

根據以上的推論，可進行以下驗證這個異常：

HiveServer產生日誌

在HUE裏執行屢次HiveSQL

手動強制關閉MySQL

手動重啓flume寫入的MySQL實例。

查看flume表現

flume進入無限循環的拋出異常狀態，驗證成功。

總結

這裏的主要緣由是MySQL服務異常致使產生的連鎖反應。權宜之計能夠在sink的代碼中提交事務出異常時，修改下sink的狀態爲BACK.OFF，防止不斷打印日誌形成機器磁盤滿影響其餘服務（待驗證）。