作者：jasonzxpan，騰訊 IEG 運營開發(fā)工程師

本文排查一個Linux 機器 CPU 毛刺問題，排查過程中不變更進程狀態(tài)、也不會影響線上服務(wù)，最后還對 CPU 毛刺帶來的風(fēng)險進行了分析和驗證。

本文中提到 CPU 統(tǒng)計和產(chǎn)生 core 文件的工具詳見 simple-perf-tools 倉庫。

問題描述

某服務(wù)所在機器統(tǒng)計顯示，其 CPU 使用率在高峰時段出現(xiàn)毛刺。

暫時未收服務(wù)調(diào)用方的不良反饋。

初步排查

查看 CPU 1 分鐘平均負載，發(fā)現(xiàn) 1 分鐘平均負載有高有低，波動明顯。說明機器上有些進程使用 CPU 波動很大。

登錄機器排查進程，使用top指令。因為 CPU 會明顯上升，重點懷疑使用 CPU 總時間高的進程，在打開 top 后，使用shift +t可以按照 CPU TIME 進行排序。

直觀的看，有幾個 spp_worker 相關(guān)的進程使用 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)四次采集的最大值上報。

因為采樣可能采到高點或者低點，當(dāng) 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 使用率的時候：

但是當(dāng) 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)計工具中取，設(shè)置 CPU 上門限觸發(fā)。

通過gdb看了幾個 coredump 文件，發(fā)現(xiàn)堆棧和函數(shù)調(diào)用基本一致。可以明確的看到，大量的耗時發(fā)生在了AddActInfoV3這一函數(shù)中：

到此位置，我們明確了高計算量發(fā)生的具體位置。

風(fēng)險點

CPU 突然飆升是否存在風(fēng)險呢？是不是計算資源充足的時候，就不會有問題呢？

這個例子中，使用的是 SPP 微線程功能，每個 Worker 進程只啟用一個線程。

如果僅僅是因為高計算量卡住 CPU，正常處理請求的邏輯將很難被調(diào)度到。這樣勢必會造成處理請求的延遲增大，甚至有超時返回的風(fēng)險。

使用 spp 的cost_stat_tool工具

利用 spp 自帶的統(tǒng)計工具印證這一風(fēng)險點，查看 worker 處理前端請求時延統(tǒng)計信息，執(zhí)行命令./cost_stat_tool -r 1：

上邊的例子中，統(tǒng)計發(fā)生配置更新前后的 5 秒鐘內(nèi)，worker 處理的 231 個請求中，有 3 個請求的處理時間超過 500ms，遠高于普通請求。

使用tcpdump抓包確認

因該服務(wù)沒有打開詳細的日志，想要進一步驗證超過 500ms 的這些請求也是正常處理的請求，而非異常請求，可以通過抓包來分析。

tcpdump?-i?any?tcp?port?20391?-Xs0?-c?5000?-w?service_spp.pcap

通過 wireshark 打開，需要過濾出返回時間 - 請求時間 > 500ms的相關(guān)請求。翻譯成 wireshark 過濾器的表達式則是：

tcp.time_delta?>?0.5?&&?tcp.dstport?!=?20391

過濾出一條符合條件的請求：

在該條記錄上右鍵 -> Follow -> TCP Stream，可以查看該請求前后的 IP 包：

上邊 4 個包分別是：

+0ms 客戶端發(fā)送請求至服務(wù)端

+38ms 服務(wù)端回復(fù) ACK，無數(shù)據(jù)

+661ms 服務(wù)端發(fā)送返回至客戶端

+662ms 客戶端回復(fù) ACK

詳細看了包中的內(nèi)容為一條普通請求，邏輯簡單，應(yīng)該在 20ms 內(nèi)返回。而此時的該進程使用 CPU 也確實為高負載的情況：

上述統(tǒng)計相互印證：

• CPU 高時，正常的網(wǎng)絡(luò)請求也會被阻塞住（回復(fù) ACK 需要 38ms，低于 40ms，與TCP 延遲確認無關(guān)）

• 平時只需要 20ms 能返回的請求，耗時了 660ms

CPU 突然飚高有風(fēng)險，需要認真對待。

歡迎關(guān)注我們的視頻號：騰訊程序員

總結(jié)

以上是生活随笔為你收集整理的Linux 机器 CPU 毛刺问题排查的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。