實時計算引擎在處理實時數據時，要保證新到來的數據被及時得到處理。例如，對于網站的訪問日志數據，假設每一分鐘有一個日志文件，那么實時計算引擎必須滿足能夠在一分鐘之內處理完這一分鐘的日志數據文件，否則會導致日志文件堆積而不能被及時處理。前幾天，量子后端團隊排查了一次實時計算引擎出現的處理延遲故障，其中使用到了ltrace和strace工具，在這里和大家分享一下。

作者: 大圓那些事 | 文章可以轉載，請以超鏈接形式標明文章原始出處和作者信息

網址: http://www.rzrgm.cn/panfeng412/archive/2012/03/26/real-time-computing-engine-processing-delay-troubleshoot.html

推薦：《Debug Hacks》

實時計算引擎在處理實時數據時，要保證新到來的數據被及時得到處理。例如，對于網站的訪問日志數據，假設每一分鐘有一個日志文件，那么實時計算引擎必須滿足能夠在一分鐘之內處理完這一分鐘的日志數據文件，否則會導致日志文件堆積而不能被及時處理。前幾天，量子后端團隊排查了一次實時計算引擎出現的處理延遲故障，其中使用到了ltrace和strace工具，在這里和大家分享一下。

1. 故障描述

當天由于大量突發異常數據的到來，導致實時計算引擎在處理每分鐘日志文件時的速度大幅下降，出現明顯的延遲現象，表現為平均每處理1分鐘文件需要2分鐘甚至更長的時間，最長可以到5分鐘，進而導致了日志文件堆積而不能被處理。

2. 故障分析

實時計算引擎在處理日志文件時，采用順次讀取各分鐘文件中的日志記錄到內存中進行計算的方式（compute過程），因此引擎在每處理完1分鐘文件時，需要進行日志的輪轉切換（rotate過程）。

實時計算引擎采用全內存計算的方式，在處理每分鐘日志文件和輪轉時，都會進行頻繁的內存操作：內存的申請和釋放（內存管理使用的是glibc庫）。在整點輪轉（rotate過程）時，會釋放掉相當一部分計算過程不再需要的內存。

經過統計后發現，實時計算引擎在處理故障當天各分鐘日志文件時的compute時間和rotate時間有如下的規律：

(1) 每分鐘日志文件的處理時間（compute時間），整點輪轉之后的前半個小時日志（如10:00~10:30的日志），每處理一分鐘日志一般都需要超過1分鐘的時間才能處理完；半點之后的日志（如10:31~11:00的日志），每處理一分鐘日志一般只需要十幾秒到一分鐘以內。

(2) 每分鐘日志文件處理后的輪轉時間（rotate時間），整點輪轉時間耗時會比其他時間長很多，整天結束時的輪轉時間最長。

以上統計信息提示我們，實時計算引擎的處理延遲就是發生在了整點rotate輪轉之后的前半個小時內，后半個小時基本可以恢復到正常水平：處理1分鐘日志文件只需要不到1分鐘時間。可見，引擎的處理延遲和整點rotate有一定的聯系，是被整點rotate所觸發產生的。具體是什么原因導致的，還需要進一步對實時計算引擎發生處理延遲時的狀態進行跟蹤才能確定。

3. 故障排查

考慮要具體跟蹤到實時計算引擎程序在發生故障時的執行情況，實時得到引擎在做什么操作（如庫函數調用、系統調用）時最耗時，才能定位到導致引擎處理延遲的根本原因，這里討論后選擇strace和ltrace工具進行排查過程。其中，strace可以跟蹤系統調用情況及耗時情況，ltrace可以跟蹤庫函數調用情況及耗時情況。

3.1 排查過程

在測試機上，使用線上版本的實時計算引擎程序，重跑觸發故障的日志數據，當整點rotate觸發引擎發生處理延遲時，開始使用ltrace和strace工具跟蹤引擎當前的運行狀態，統計引擎在系統調用和庫函數上的調用時間開銷。

1. 跟蹤庫函數的耗時情況：ltrace -fp pid -T –c
2. 跟蹤系統調用的耗時情況：strace -fp pid –T –c

3.2 排查結果

以下是對排查過程的結果分析：

1. 測試發現在整點rotate時，CPU 100%用在了用戶空間，日志處理到整點時，系統的空閑內存已經被用盡，所有的內存被page cache或者進程使用。
2. 使用ltrace跟蹤發現，malloc較大內存塊時（如大于1000字節），其執行時間較長，大約2~4秒鐘，這個是ltrace統計到的耗時最多的庫調用，引擎的大部分時間都花費在了malloc上。
3. 使用strace跟蹤系統調用，發現在malloc內存的時候，沒有任何系統調用發送到內核空間。再加上CPU 100%消耗在用戶空間，基本上可以判斷，malloc的時間都耗費在glibc的內存管理模塊中，推測可能是由內存碎片引起的，當程序申請分配較大內存塊時，它會整理內存碎片從而形成較大的內存塊分配給計算引擎。
4. 為 了進一步驗證第3步的結論，我們使用google的tcmalloc進行測試（export LD_PRELOAD="./libtcmalloc.so"）。測試結果發現使用tcmalloc后，實時計算引擎恢復正常，每個日志文件的處理時間從幾分鐘降到幾秒鐘，整點rotate時間也從十幾分鐘降到30~40秒。

4. 解決方法

由于本次實時計算引擎的處理延遲問題最終定位到是出在glibc的內存管理上，一個簡單的解決方案是用tcmalloc替換glibc。但是從長遠來看，是否需要我們自己實現內存管理模塊，取決于人力資源情況和tcmalloc的發展情況。

5. 經驗教訓

1. 避免只依賴于經驗進行故障排查，要結合代碼實現邏輯和故障現場環境進行分析。
2. 數據才是最真實可靠的，包括現場收集到的數據，歷史的數據，這些都是分析定位故障的重要依據。
3. 沒有哪種工具是通用的，必須結合實際情況，選擇使用合適的調試跟蹤工具，積累相關使用經驗。

最后，感謝這次一起排查問題的同事們：太奇、澄蒼、民瞻、淵虹。你們都很牛！