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