一次應用 CPU 飆高的血案排查過程
案件背景
一個應用叢集裡,時不時會有幾臺機器出現cpu打滿現象,開始沒有引起重視,後來連續出現報警,開始著手對其中一臺進行排查,現將破案記錄如下。
cpu飆升這類案件,一般來說有幾個物件嫌疑重大:
-
嫌犯A:記憶體洩漏,導致大量full GC
-
嫌犯B:宿主機cpu超賣
-
嫌犯C:程式碼存在死迴圈
鎖定嫌犯
嫌犯A:記憶體洩漏?
從monitor上看到,這臺機器cpu佔用達到300%多,而GC一覽並沒有出現full GC,只是出現了一些常規的YGC。再觀察堆記憶體使用情況,也屬正常,先排出了oom的嫌疑。
嫌犯B:cpu超賣?
虛擬機器和容器技術突飛猛進,一臺宿主機上跑多個vm帶來了很多便利,vm間大多時候都能和諧共處,但偶爾也會出現某個問題vm大量佔用宿主機資源,導致其他vm受到影響,也是超賣問題
到底是不是超賣在搞鬼呢?登上機器top一把,一探究竟
top
這裡看到Cpu(s)一欄,cpu佔用主要來自us,而st(Steal Time)並不高,這說明cpu的消耗並非來自宿主機的超賣,而是應用自身的消耗。所以排出超賣的嫌疑。
鎖定嫌犯C:死迴圈
排出了上面兩位的嫌疑,看來只能繼續深入應用內部,對犯案現場勘察,查明哪些執行緒在消耗cpu資源。
前面通過top命令拿到java應用的pid是2143,通過top -Hp pid 命令,檢視程序內的執行緒情況:
top -Hp 2143
不看不知道,一看嚇一跳,犯罪現場觸目驚心!前幾個執行緒都佔用了大量cpu,並且佔用cpu時間最長的一個執行緒(tid=32421),已經存活了5個多小時。
繼續進行追查,這貨到底在幹啥?
printf "%x" 32421 -- 拿到十六進位制
jstack pid | grep tid -- 檢視執行緒情況
原來這個執行緒在HashMap.getEntry()這,執行緒狀態顯示是RUNNABLE,說明並沒有出現死鎖(Blocked),而是不停run了5個多小時,看來凶犯已經找到:死迴圈非他莫屬了!
為了進一步確認,用類似方法一一盤查其他幾個高cpu佔用的執行緒,從招供來看都是類似的堆疊。同時,在psp上進行了一把dump,用Zprofiler分析了一把,除去一些正常的執行緒,還有不少共犯混跡其中。
作案手法
凶手已經找到,但它是如何作案的呢?也就是這個死迴圈是如何產生的?
HashMap的併發問題
上面的堆疊告訴我們,執行緒在HashMap.java:465行不停的run,從jdk7的原始碼(應用使用的版本)可以看到
原來問題出在 e.next 這個地方。
看過原始碼的同學都知道,jdk(6)7的HashMap是陣列+連結串列的儲存結構(jdk8優化加入了紅黑樹)。
為了在查詢效率方面達到平衡,HashMap的size是動態變化的,size初始值是16(未指定情況下)。一般來說,Hash表這個容器當有資料要插入(put->addEntry)時,會檢查容量有沒有超過設定的thredhold,如果超過,需要增大Hash表的尺寸,這一過程稱為resize。
resize()原始碼如下:
可見,在多執行緒同時呼叫put方法時,多個執行緒也會同時進入transfer(),也就到了併發問題的核心地帶。
這段 程式碼會重新 構建陣列和連結串列,這單執行緒下安全,但多個執行緒同時去操作連結串列,會出現意想不到的結果,比如A執行緒操作到一半被掛起,B執行緒對A正在操作的連結串列進行了挪動,然後A獲得cpu資源繼續操作,原先的連結串列元素可能已經被挪到其他位置。
這會造成 部分資料丟失,有一定機率出現更糟的情況:環連結串列
那麼回到之前的getEntry方法,出現環連結串列的情況下,e.next會出現無限迴圈,無法跳出的情況。
總結下,多執行緒同時put時,有一定機率導致環連結串列產生,導致get方法進入無限迴圈,進而導致了cpu飆高。
結案
到這裡,真相已經浮出水面:二方包的一個工具類(靜態類),使用了一個static的HashMap進行了併發操作,導致了併發問題。