查看cpu使用率_腾讯游戏开发工程师：Linux 机器 CPU 毛刺问题排查
作者：jasonzxpan，騰訊 IEG 運(yùn)營開發(fā)工程師
本文排查一個Linux 機(jī)器 CPU 毛刺問題，排查過程中不變更進(jìn)程狀態(tài)、也不會影響線上服務(wù)，最后還對 CPU 毛刺帶來的風(fēng)險進(jìn)行了分析和驗(yàn)證。
本文中提到 CPU 統(tǒng)計(jì)和產(chǎn)生 core 文件的工具詳見 simple-perf-tools 倉庫。
問題描述
某服務(wù)所在機(jī)器統(tǒng)計(jì)顯示，其 CPU 使用率在高峰時段出現(xiàn)毛刺。
暫時未收服務(wù)調(diào)用方的不良反饋。
初步排查
查看 CPU 1 分鐘平均負(fù)載，發(fā)現(xiàn) 1 分鐘平均負(fù)載有高有低，波動明顯。說明機(jī)器上有些進(jìn)程使用 CPU 波動很大。
登錄機(jī)器排查進(jìn)程，使用top指令。因?yàn)?CPU 會明顯上升，重點(diǎn)懷疑使用 CPU 總時間高的進(jìn)程，在打開 top 后，使用shift +t可以按照 CPU TIME 進(jìn)行排序。
直觀的看，有幾個 spp_worker 相關(guān)的進(jìn)程使用 CPU TIME 相對較高。
第一個進(jìn)程因?yàn)閱拥臅r間比較長，所以 CPU TIME 也比較大。可以使用下面的腳本，計(jì)算各個進(jìn)程從各自拉起后 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%s%11.3f",?$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 進(jìn)程監(jiān)控器 CPU 使用率：
可以發(fā)現(xiàn)其 CPU 大部分情況很低，但是在某一個時間點(diǎn)會升高，持續(xù) 1 秒左右。而且大部分時間是耗費(fèi)在用戶態(tài)，而非系統(tǒng)調(diào)用。
而《Linux Agent 采集項(xiàng)說明 - CPU 使用率》中描述的 CPU 使用率的采樣策略為：
Linux Agent 每分鐘會采集 4 次 15 秒內(nèi)的 CPU 平均使用率。為了避免漏采集 CPU 峰值，網(wǎng)管 Agent 取這一分鐘內(nèi)四次采集的最大值上報(bào)。
因?yàn)椴蓸涌赡懿傻礁唿c(diǎn)或者低點(diǎn)，當(dāng) 1 分鐘內(nèi)出現(xiàn) CPU 飆升，則會表現(xiàn)為尖峰；如果四次都沒有出現(xiàn)飆升，則表現(xiàn)為低谷。
至此，已經(jīng)能確認(rèn)是這批 Worker 進(jìn)程引起了這種毛刺，但具體是哪部分代碼有問題還需要進(jìn)一步排查。
進(jìn)一步排查
前邊確認(rèn)了沒有太多的系統(tǒng)調(diào)用，所以不必使用strace工具。
使用perf工具
使用perf工具進(jìn)行查看。具體的命令是perf top -p 45558，在低 CPU 使用率的時候：
但是當(dāng) CPU 飚上去的時候，perf采樣的位置變成如下這樣：
看一下紅框的位置，可以發(fā)現(xiàn)可能是配置更新部分有問題，因?yàn)?#xff1a;
- 這個地方 Protobuf 特別多的地方，在做更新的操作(有MergeFrom，有Delete)
- 有大量的用到了std::map(有std::_Rb_tree，有字符串比較)
通過觀察perf結(jié)果的方法，雖然能夠猜測大計(jì)算量的位置，但是有兩個不便之處：
- 如果 CPU 高的情況發(fā)生概率很低，人為觀察比較耗時
- 不能明確的知道，具體在哪個文件的哪個函數(shù)
使用gcore
最初統(tǒng)計(jì)的時候，發(fā)現(xiàn) CPU 高的情況會出現(xiàn) 1 秒多的時間，如果發(fā)現(xiàn) CPU 高負(fù)載時，直接調(diào)用gcore {pid}的命令，可以保留堆棧信息，明確具體高負(fù)載的位置。
將使用 gcore 的指令，添加到統(tǒng)計(jì)工具中取，設(shè)置 CPU 上門先觸發(fā)。
通過gdb看了幾個 coredump 文件，發(fā)現(xiàn)堆棧和函數(shù)調(diào)用基本一致。可以明確的看到，大量的耗時發(fā)生在了AddActInfoV3這一函數(shù)中：
到此位置，我們明確了高計(jì)算量發(fā)生的具體位置。
風(fēng)險點(diǎn)
CPU 突然飆升是否存在風(fēng)險呢？是不是計(jì)算資源充足的時候，就不會有問題呢？
這個例子中，使用的是 SPP 微線程功能，每個 Worker 進(jìn)程只啟用一個線程。
如果僅僅是因?yàn)楦哂?jì)算量卡住 CPU，正常處理請求的邏輯將很難被調(diào)度到。這樣勢必會造成處理請求的延遲增大，甚至有超時返回的風(fēng)險。
使用 spp 的cost_stat_tool工具
利用 spp 自帶的統(tǒng)計(jì)工具印證這一風(fēng)險點(diǎn)，查看 worker 處理前端請求時延統(tǒng)計(jì)信息，執(zhí)行命令./cost_stat_tool -r 1：
上邊的例子中，統(tǒng)計(jì)發(fā)生配置更新前后的 5 秒鐘內(nèi)，worker 處理的 231 個請求中，有 3 個請求的處理時間超過 500ms，遠(yuǎn)高于普通請求。
使用tcpdump抓包確認(rèn)
因該服務(wù)沒有打開詳細(xì)的日志，想要進(jìn)一步驗(yàn)證超過 500ms 的這些請求也是正常處理的請求，而非異常請求，可以通過抓包來分析。
tcpdump?-i?any?tcp?port?20391?-Xs0?-c?5000?-w?service_spp.pcap通過 wireshark 打開，需要過濾出返回時間 - 請求時間 > 500ms的相關(guān)請求。翻譯成 wireshark 過濾器的表達(dá)式則是：
tcp.time_delta?>?0.5?&&?tcp.dstport?!=?20391過濾出一條符合條件的請求：
在該條記錄上右鍵 -> Follow -> TCP Stream，可以查看該請求前后的 IP 包：
上邊 4 個包分別是：
詳細(xì)看了包中的內(nèi)容為一條普通請求，邏輯簡單，應(yīng)該在 20ms 內(nèi)返回。而此時的該進(jìn)程使用 CPU 也確實(shí)為高負(fù)載的情況：
上述統(tǒng)計(jì)相互印證：
- CPU 高時，正常的網(wǎng)絡(luò)請求也會被阻塞住(回復(fù) ACK 需要 38ms，低于 40ms，與TCP 延遲確認(rèn)無關(guān))
- 平時只需要 20ms 能返回的請求，耗時了 660ms
CPU 突然飚高有風(fēng)險，需要認(rèn)真對待。
總結(jié)
以上是生活随笔為你收集整理的查看cpu使用率_腾讯游戏开发工程师：Linux 机器 CPU 毛刺问题排查的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： python算不算编程_Python 并
- 下一篇： 阿里云物联网平台python开发手册_阿