騰訊開發(fā)工程師：Linux 機器 CPU 毛刺問題排查
本文排查一個Linux 機器 CPU 毛刺問題，排查過程中不變更進程狀態(tài)、也不會影響線上服務，最后還對 CPU 毛刺帶來的風險進行了分析和驗證。
本文中提到 CPU 統(tǒng)計和產(chǎn)生 core 文件的工具詳見 simple-perf-tools 倉庫。
問題描述
某服務所在機器統(tǒng)計顯示，其 CPU 使用率在高峰時段出現(xiàn)毛刺。
暫時未收服務調(diào)用方的不良反饋。
初步排查
查看 CPU 1 分鐘平均負載，發(fā)現(xiàn) 1 分鐘平均負載有高有低，波動明顯。說明機器上有些進程使用 CPU 波動很大。
登錄機器排查進程，使用top指令。因為 CPU 會明顯上升，重點懷疑使用 CPU 總時間高的進程，在打開 top 后，使用shift +t可以按照 CPU TIME 進行排序。
直觀的看，有幾個 spp_worker 相關的進程使用 CPU TIME 相對較高。
第一個進程因為啟動的時間比較長，所以 CPU TIME 也比較大?？梢允褂孟旅娴哪_本，計算各個進程從各自拉起后 CPU 使用率：
- uptime=`awk '{print $1}' /proc/uptime` # why is it too slow indocker?
- hertz=`zcat /proc/config.gz | grep CONFIG_HZ= |awk -F"=" '{print $2}'`
- awk -v uptime=$uptime -v hertz=$hertz -- '{printf("%d\t%s\t%11.3f\n", $1, $2, (100 *($14 + $15) / (hertz * uptime - $22)));}' /proc/*/stat 2> /dev/null | sort -gr -k +3 | head -n 20
看到的也是這些 spp_worker 使用 CPU 相對要高一些：
選其中的一個 PID 為 45558 的 Worker 進程監(jiān)控器 CPU 使用率：
可以發(fā)現(xiàn)其 CPU 大部分情況很低，但是在某一個時間點會升高，持續(xù) 1 秒左右。而且大部分時間是耗費在用戶態(tài)，而非系統(tǒng)調(diào)用。
而《Linux Agent 采集項說明 - CPU 使用率》中描述的 CPU 使用率的采樣策略為：
Linux Agent 每分鐘會采集 4 次 15 秒內(nèi)的 CPU 平均使用率。為了避免漏采集 CPU 峰值，網(wǎng)管 Agent 取這一分鐘內(nèi)四次采集的最大值上報。
因為采樣可能采到高點或者低點，當 1 分鐘內(nèi)出現(xiàn) CPU 飆升，則會表現(xiàn)為尖峰；如果四次都沒有出現(xiàn)飆升，則表現(xiàn)為低谷。
至此，已經(jīng)能確認是這批 Worker 進程引起了這種毛刺，但具體是哪部分代碼有問題還需要進一步排查。
進一步排查
前邊確認了沒有太多的系統(tǒng)調(diào)用，所以不必使用strace工具。
使用perf工具
使用perf工具進行查看。具體的命令是perf top -p 45558，在低 CPU 使用率的時候：
但是當 CPU 飚上去的時候，perf采樣的位置變成如下這樣：
看一下紅框的位置，可以發(fā)現(xiàn)可能是配置更新部分有問題，因為：
- 這個地方 Protobuf 特別多的地方，在做更新的操作（有MergeFrom，有Delete）
- 有大量的用到了std::map（有std::_Rb_tree，有字符串比較）
通過觀察perf結(jié)果的方法，雖然能夠猜測大計算量的位置，但是有兩個不便之處：
- 如果 CPU 高的情況發(fā)生概率很低，人為觀察比較耗時
- 不能明確的知道，具體在哪個文件的哪個函數(shù)
使用gcore
最初統(tǒng)計的時候，發(fā)現(xiàn) CPU 高的情況會出現(xiàn) 1 秒多的時間，如果發(fā)現(xiàn) CPU 高負載時，直接調(diào)用gcore {pid}的命令，可以保留堆棧信息，明確具體高負載的位置。
將使用 gcore 的指令，添加到統(tǒng)計工具中取，設置 CPU 上門先觸發(fā)。
通過gdb看了幾個 coredump 文件，發(fā)現(xiàn)堆棧和函數(shù)調(diào)用基本一致。可以明確的看到，大量的耗時發(fā)生在了AddActInfoV3這一函數(shù)中：
到此位置，我們明確了高計算量發(fā)生的具體位置。
風險點
CPU 突然飆升是否存在風險呢？是不是計算資源充足的時候，就不會有問題呢？
這個例子中，使用的是 SPP 微線程功能，每個 Worker 進程只啟用一個線程。
如果僅僅是因為高計算量卡住 CPU，正常處理請求的邏輯將很難被調(diào)度到。這樣勢必會造成處理請求的延遲增大，甚至有超時返回的風險。
使用 spp 的cost_stat_tool工具
利用 spp 自帶的統(tǒng)計工具印證這一風險點，查看 worker 處理前端請求時延統(tǒng)計信息，執(zhí)行命令./cost_stat_tool -r 1：
上邊的例子中，統(tǒng)計發(fā)生配置更新前后的 5 秒鐘內(nèi)，worker 處理的 231 個請求中，有 3 個請求的處理時間超過 500ms，遠高于普通請求。
使用tcpdump抓包確認
因該服務沒有打開詳細的日志，想要進一步驗證超過 500ms 的這些請求也是正常處理的請求，而非異常請求，可以通過抓包來分析。
- tcpdump -i any tcp port 20391 -Xs0 -c 5000 -w service_spp.pcap
通過 wireshark 打開，需要過濾出返回時間 - 請求時間 > 500ms的相關請求。翻譯成 wireshark 過濾器的表達式則是：
- tcp.time_delta > 0.5 && tcp.dstport != 20391
過濾出一條符合條件的請求：
在該條記錄上右鍵 -> Follow -> TCP Stream，可以查看該請求前后的 IP 包：
上邊 4 個包分別是：
- +0ms 客戶端發(fā)送請求至服務端
- +38ms 服務端回復 ACK，無數(shù)據(jù)
- +661ms 服務端發(fā)送返回至客戶端
- +662ms 客戶端回復 ACK
詳細看了包中的內(nèi)容為一條普通請求，邏輯簡單，應該在 20ms 內(nèi)返回。而此時的該進程使用 CPU 也確實為高負載的情況：
上述統(tǒng)計相互印證：
- CPU 高時，正常的網(wǎng)絡請求也會被阻塞?。ɑ貜?ACK 需要 38ms，低于 40ms，與TCP 延遲確認無關）
- 平時只需要 20ms 能返回的請求，耗時了 660ms
CPU 突然飚高有風險，需要認真對待。
