一次線上 CPU 飆升問題的分析解決

田爽Poison發表於2017-09-14

前幾日,下了班在家時突然收到監控報警,線上一組業務機器 CPU 被打滿至 100%,為了保持服務的穩定執行,臨時採取了升級配置、加機器等粗暴的方法將當晚扛了過去。
半夜想了下可能的原因,由於可能因素太多,不能確定,第二天到公司後,在一臺預發機器上把 Java Mission Control 所需的引數配置好,然後就等待下一次問題出現唄,果然,沒幾天,在晚高峰時問題又復現了,馬上將線上的流量分了一小部分到提前配置好的預發機器上,沒過一會,預發機器的 負載 也滿了。在 Java Mission Control 的 Thread 的皮膚裡觀察了一會,業務執行緒的 CPU 使用率根本不高,超過 10% 的都很少,但此時 CPU 又是被打滿的,在不停檢視 Java Mission Control 中提供的資訊時,發現了 Full GC 非常頻繁,在應用啟動了兩個多小時內,Full GC 了 1500 多次,佔用了 13 多分鐘,並且次數和時間依然在不停增加中,一下讓筆者想到了之前在相關書籍上提到的頻繁 Full GC 的相關問題,沒想到在這裡讓筆者給碰上了,如圖:

prepub Full GC
prepub Full GC

但是預發機器和線上機器配置是不一樣的啊,預發是 Full GC 導致的 CPU 飆升不能代表線上機器也是這個原因啊,為了驗證此問題,筆者在其中一臺線上機器配置了 GC log 等引數,就等著線上問題再出現時能留下相關日誌資訊,GC log 相關知識可參考: Understanding the Java Garbage Collection Log 。是否感覺肉眼分析 GC log 很麻煩?好吧,早就有人做好了相關分析工具: GC easy

這裡提供一份 GC log,是在一臺線上 1Core 4G 的機器上採集的 (JVM 未調優),也是到了晚高峰 CPU 就 100% 了,可以自行上傳到 GC easy 分析看看,點此 下載

一圖勝千言:

Full GC
Full GC

為了檢查是否有部分業務執行緒存在大幅使用 CPU 的情況,筆者也順便準備了 生成執行緒轉儲 相關命令,如:先用 jps 找出 tomcat 的 pid,然後使用如下命令生成執行緒轉儲:

jstack -l <pid> > /opt/threadDump.txt複製程式碼

為了保證資料的準確性,在 CPU 被打滿的時間段內筆者生成了五六份以備後面分析,同樣,用肉眼觀察總是比較艱難,此處可利用 Java Thread Dump Analyzer 進行分析。這一塊線上上機器上的分析和筆者之前在預發機器上觀察的現象一致,沒有存在大量消耗 CPU 的問題執行緒。

到此為止,問題總算找到了,只要找到原因所在,解決總是比較簡單的,之前由於這組業務量不大,就沒有進行 JVM 調優,使用的預設的 JVM 相關引數,比如在 1Core 4G 的機器上,預設 最大堆記憶體 為物理的記憶體的四分之一,還有很多記憶體沒有得到利用,後面的解決辦法也不用寫了,調整後觀察了一週,到目前為止晚高峰時服務依然很穩定,負載也在預期的範圍內,沒有再出現 CPU 飆升的情況,問題得到解決。

ELIMINATE CONSECUTIVE FULL GCs
深入理解 Java 虛擬機器(第2版)
Java 效能權威指南

原文地址

相關文章