最近線上頻繁收到CPU超過閾值的告警, 很明顯是哪里出了問題.
于是排查了一番, 到最后找到罪魁禍首的時候, 突然意識到這次是一次很有意思的"非典型"的CPU的問題, 所以這里特意記錄一下.
為啥說它是非典型呢, 因為在我的經(jīng)驗里, 典型的CPU飆升通常都是業(yè)務(wù)代碼里面有死循環(huán), 或是某個RPC性能過低阻塞了大量線程等等,
而這次的CPU問題卻是由GC引起的, 因吹斯汀
來看看排查過程
找出占用CPU的線程
top
首先肯定是先看哪些線程占用CPU最高, 這個可以使用top命令:
top -Hp $pid -b -n 1|sed -n "7,17p"
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
94349 app 20 0 11.2g 5.0g 12m S 15.0 32.1 215:03.69 java
94357 app 20 0 11.2g 5.0g 12m S 15.0 32.1 88:22.39 java
94352 app 20 0 11.2g 5.0g 12m S 13.1 32.1 215:05.71 java
94350 app 20 0 11.2g 5.0g 12m S 11.2 32.1 215:04.86 java
94351 app 20 0 11.2g 5.0g 12m S 11.2 32.1 215:04.99 java
94935 app 20 0 11.2g 5.0g 12m S 11.2 32.1 63:11.75 java
94926 app 20 0 11.2g 5.0g 12m S 9.4 32.1 63:10.58 java
94927 app 20 0 11.2g 5.0g 12m S 5.6 32.1 63:06.89 java
94932 app 20 0 11.2g 5.0g 12m S 5.6 32.1 63:12.65 java
94939 app 20 0 11.2g 5.0g 12m S 5.6 32.1 63:01.75 java
$pid是我們對應(yīng)的java進程的進程ID, sed -n "7,17p" 是取第7到第17行, 因為前7行都是top命令的頭部信息, 所以第7到第17行就是該線程下最耗CPU的前10個線程了.
其中第一列的"pid"就是JVM里面對應(yīng)的線程ID, 我們只需要用線程ID在jstack里面找到對應(yīng)的線程就知道是誰在搞鬼了.
不過需注意的是top命令中的PID是十進制的, 而jstack里面的線程ID是十六進制的, 所以我們還需要做一個工作, 就是把上面的PID轉(zhuǎn)成十六進制, 這里我只轉(zhuǎn)換了最耗CPU的前3個:
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94349
1708d
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94357
17095
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94352
17090
jstack
現(xiàn)在我們已經(jīng)知道消耗CPU的線程ID, 接著就要去看看這些線程ID對應(yīng)的是什么線程.
首先使用jstack打出JVM里面的所有的線程信息:
[app@linux-v-l-02:/app/tmp/]jstack -l $pid >>/tmp/jstack.txt
值得一提的是, 由于JVM里面的線程一直在變化, 而TOP中的線程也一直在變化, 所以如果jstack命令和top命令是分開執(zhí)行的話, 很有可能兩者的線程ID會對應(yīng)不上. 因此top命令和jstack命令最好是寫好腳本一起執(zhí)行. 其實我就是寫腳本一起執(zhí)行的~
接著, 看看1708d, 17095, 17090 這三個到底是什么線程:
[app@linux-v-l-02:/app/tmp/]$egrep "1708d|17095|17090" jstack.txt --color
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c023000 nid=0x1708d runnable
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c028800 nid=0x17090 runnable
"G1 Concurrent Refinement Thread#0" os_prio=0 tid=0x00007f4d4c032000 nid=0x17095 runnable
上面的nid就是對應(yīng)的十六進制的線程ID. 從jstack可以看出, 居然最耗CPU的線程都是一些GC線程.
對JVM的FULL GC我們是有監(jiān)控的, 這個應(yīng)用自從換了G1之后, 一般一周左右才會發(fā)生一次FULL GC, 所以我們一直都以為我們的JVM堆是很健康的, 但很種種跡象表明, 我們的JVM確實是出問題了
GC問題
gc日志
GC日志我們是一直有打印, 打開一看, 果然是有非常多的GC pause, 如下
2019-08-12T20:12:23.002+0800: 501598.612: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0907586 secs]
[Parallel Time: 84.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501598615.0, Avg: 501598615.0, Max: 501598615.0, Diff: 0.1]
[Ext Root Scanning (ms): Min: 4.9, Avg: 5.0, Max: 5.0, Diff: 0.2, Sum: 19.8]
[Update RS (ms): Min: 76.6, Avg: 76.7, Max: 76.7, Diff: 0.1, Sum: 306.7]
[Processed Buffers: Min: 945, Avg: 967.0, Max: 1007, Diff: 62, Sum: 3868]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 2.4, Avg: 2.5, Max: 2.6, Diff: 0.2, Sum: 9.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 84.2, Avg: 84.2, Max: 84.2, Diff: 0.1, Sum: 336.7]
[GC Worker End (ms): Min: 501598699.2, Avg: 501598699.2, Max: 501598699.2, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 5.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.3 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.7 ms]
[Free CSet: 0.2 ms]
[Eden: 230.0M(1968.0M)->0.0B(1970.0M) Survivors: 8192.0K->8192.0K Heap: 1693.6M(4096.0M)->1082.1M(4096.0M)]
[Times: user=0.34 sys=0.00, real=0.10 secs]
2019-08-12T20:12:23.094+0800: 501598.703: [GC concurrent-root-region-scan-start]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-root-region-scan-end, 0.0076353 secs]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-mark-start]
2019-08-12T20:12:23.634+0800: 501599.243: [GC concurrent-mark-end, 0.5323465 secs]
2019-08-12T20:12:23.639+0800: 501599.249: [GC remark 2019-08-12T20:12:23.639+0800: 501599.249: [Finalize Marking, 0.0019652 secs] 2019-08-12T20:12:23.641+0800: 501599.251: [GC ref-proc, 0.0027393 secs] 2019-08-12T20:12:23.644+0800: 501599.254: [Unloading, 0.0307159 secs], 0.0366784 secs]
[Times: user=0.13 sys=0.00, real=0.04 secs]
2019-08-12T20:12:23.682+0800: 501599.291: [GC cleanup 1245M->1226M(4096M), 0.0041762 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-start]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-end, 0.0000487 secs]
2019-08-12T20:12:30.022+0800: 501605.632: [GC pause (G1 Humongous Allocation) (young) (to-space exhausted), 0.3849037 secs]
[Parallel Time: 165.7 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501605635.2, Avg: 501605635.2, Max: 501605635.3, Diff: 0.1]
[Ext Root Scanning (ms): Min: 3.5, Avg: 3.8, Max: 4.4, Diff: 0.9, Sum: 15.2]
[Update RS (ms): Min: 135.5, Avg: 135.8, Max: 136.0, Diff: 0.5, Sum: 543.3]
[Processed Buffers: Min: 1641, Avg: 1702.2, Max: 1772, Diff: 131, Sum: 6809]
[Scan RS (ms): Min: 1.5, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 24.1, Avg: 24.4, Max: 24.6, Diff: 0.4, Sum: 97.4]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 165.6, Avg: 165.6, Max: 165.6, Diff: 0.0, Sum: 662.4]
[GC Worker End (ms): Min: 501605800.8, Avg: 501605800.9, Max: 501605800.9, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 218.7 ms]
[Evacuation Failure: 210.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.5 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 2.2 ms]
[Free CSet: 0.2 ms]
[Eden: 666.0M(1970.0M)->0.0B(204.0M) Survivors: 8192.0K->0.0B Heap: 2909.5M(4096.0M)->1712.4M(4096.0M)]
[Times: user=1.44 sys=0.00, real=0.39 secs]
2019-08-12T20:12:32.225+0800: 501607.834: [GC pause (G1 Evacuation Pause) (mixed), 0.0800708 secs]
[Parallel Time: 74.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501607835.5, Avg: 501607835.6, Max: 501607835.6, Diff: 0.1]
[Ext Root Scanning (ms): Min: 3.7, Avg: 4.0, Max: 4.4, Diff: 0.6, Sum: 16.2]
[Update RS (ms): Min: 67.8, Avg: 68.0, Max: 68.1, Diff: 0.3, Sum: 272.0]
[Processed Buffers: Min: 863, Avg: 899.8, Max: 938, Diff: 75, Sum: 3599]
G1的日志有個不好的地方就是太多了, 看得眼花繚亂, 為了方便描述, 我將上述GC日志省略一些無意義的, 濃縮為以下三段:
2019-08-12T20:12:23.002+0800: 501598.612: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0907586 secs]
[Parallel Time: 84.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501598615.0, Avg: 501598615.0, Max: 501598615.0, Diff: 0.1]
......
[Eden: 230.0M(1968.0M)->0.0B(1970.0M) Survivors: 8192.0K->8192.0K Heap: 1693.6M(4096.0M)->1082.1M(4096.0M)]
[Times: user=0.34 sys=0.00, real=0.10 secs]
2019-08-12T20:12:23.094+0800: 501598.703: [GC concurrent-root-region-scan-start]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-root-region-scan-end, 0.0076353 secs]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-mark-start]
2019-08-12T20:12:23.634+0800: 501599.243: [GC concurrent-mark-end, 0.5323465 secs]
2019-08-12T20:12:23.639+0800: 501599.249: [GC remark 2019-08-12T20:12:23.639+0800: 501599.249: [Finalize Marking, 0.0019652 secs] 2019-08-12T20:12:23.641+0800: 501599.251: [GC ref-proc, 0.0027393 secs] 2019-08-12T20:12:23.644+0800: 501599.254: [Unloading, 0.0307159 secs], 0.0366784 secs]
[Times: user=0.13 sys=0.00, real=0.04 secs]
2019-08-12T20:12:23.682+0800: 501599.291: [GC cleanup 1245M->1226M(4096M), 0.0041762 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-start]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-end, 0.0000487 secs]
2019-08-12T20:12:30.022+0800: 501605.632: [GC pause (G1 Humongous Allocation) (young) (to-space exhausted), 0.3849037 secs]
[Parallel Time: 165.7 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501605635.2, Avg: 501605635.2, Max: 501605635.3, Diff: 0.1]
......
[Eden: 666.0M(1970.0M)->0.0B(204.0M) Survivors: 8192.0K->0.0B Heap: 2909.5M(4096.0M)->1712.4M(4096.0M)]
[Times: user=1.44 sys=0.00, real=0.39 secs]
2019-08-12T20:12:32.225+0800: 501607.834: [GC pause (G1 Evacuation Pause) (mixed), 0.0800708 secs]
[Parallel Time: 74.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501607835.5, Avg: 501607835.6, Max: 501607835.6, Diff: 0.1]
......
這段日志看著就清晰多了, 首先從日志里面就能看出至少3個問題:
- 出現(xiàn)了mixed類型的Evacuation Pause
- 頻繁G1 Humongous Allocation導(dǎo)致的to-space exhausted, 說明大量的大對象不斷地分配出來
- GC pause時間達到0.3849037 secs, 這是我們最不可容忍的
另外還有一個更嚴重的問題這里是看不出來的, 就是類似的日志非常頻繁! 高峰時期基本就是每2秒鐘打印出一次
jmap -histo
通過上面的GC日志, 我們基本可以判斷, 是應(yīng)用程序不斷地new一些大對象導(dǎo)致的.
那什么是大對象呢?
一般情況就是局部變量的List, 通巢右猓可以通過jmap -histo來查看堆內(nèi)哪些對象占用內(nèi)存比較大, 實例數(shù)是多少
所以, 先通過jmap -histo $pid來看看堆棧里面的對象分布是如何的:
num #instances #bytes class name
--------------------------------------------
1: 1120 1032796420 [B
2: 838370 105246813 [C
3: 117631 55348463 [I
4: 352652 31033457 java.lang.reflect.Method
5: 665505 13978410 java.lang.String
6: 198567 12368412 [Ljava.lang.Object
7: 268941 9467465 java.util.HashMap$Node
8: 268941 8064567 java.util.treeMap$Entry
9: 268941 7845665 java.lang.reflect.Field
10: 268941 7754771 [Ljava.util.HashMap$Node
....
一般來說, 如果運氣好, 而且業(yè)務(wù)代碼有問題的, 通常能在jmap -histo里面看到我們業(yè)務(wù)涉及到的類名的.
但是很可惜, 這里沒有.
然而, 聰明的同學可能一眼就看出了這個堆其實是很有問題的.
我們看排行第一的[B (byte數(shù)組), 占用了堆大小1032796420(1G左右), 而instances卻只有1120多個, 簡單地一相除, 居然每個對象能有1M大小!
很明顯, 這就是我們要找的大對象了, 但是只知道是一些byte數(shù)組, 并不知道是什么數(shù)組, 所以還需要進一步排查
為什么1M就是大對象了呢? 由于我們的堆只有4G大小, 一般G1最大只有2048個region, 因此每個region的大小就是2M. G1在分配新生代的對象的內(nèi)存空間時, 發(fā)現(xiàn)這個對象大于region size的一半, 就可以認為是大對象了,故而發(fā)生G1 Humongous Allocation
jmap -dump:format=b
使用jmap -dump:format=b,file=head.hprof $pid 命令可以把JVM的堆內(nèi)容dump出來. dump出來后一般直接在命令行查看是看不出什么的, 得下載到本地, 借助一些分析工具來進行分析. 可以有很多工具可以分析, 例如jvisualvm, jprofile, MAT等等
這里我用到的是jvisualvm, 打開jvisualvm==>文件==>裝入==>選中我剛剛下載下來的head.hprof, 然后再點擊"類", 再點擊按大小排序, 可以得到如下圖.
可以看出, 堆里面的byte數(shù)組實例數(shù)占比只有0.9%, 內(nèi)存大小占比卻高達30%, 說明每一個實例都是大對象.
接下來我們雙擊第一行的"byte[]" 查看這些byte數(shù)組的明細. 可以看很多的對象都是1048600byte, 也就是剛好1M, 不過這樣還是看不出這個數(shù)組的內(nèi)容, 所以我們導(dǎo)出這個數(shù)組到本地, 如下圖:
導(dǎo)出后先用Sublime Text打開看一下, 如下圖
可以看到,這個數(shù)組實際大小只有1k左右(數(shù)前面的非0的數(shù)字的個數(shù)), 后面都是一些無意義的0值.
雖然還無法確定這個數(shù)組是什么代碼產(chǎn)生的, 但是至少可以大概確定了問題產(chǎn)生的原因:
肯定是某處代碼new了一個1048600大的byte數(shù)組,而實際場景中這個byte數(shù)組只需要1k左右即可,后面沒有填充的位都是默認的0值
最后證實一下我們的猜測,簡單的用
String str= new String (bytearr, "UTF-8");
System.out.println("str = [" + str + "]");
把數(shù)組內(nèi)容打印出來, 打印結(jié)果大概如下(我省略了大部分內(nèi)容):
str = [p? C0+org.apache.camel.impl.DefaultExchangeHolder?
exchangeId?inFaultFlagoutFaultFlag exception?inBody?outBody inHeaders
outHeaders
remoteOptRole?faceUrl?version?fromIfromUser?failFaceUrl
.....
再用相關(guān)的關(guān)鍵詞搜索一下代碼,最后找出了真兇:
data = DefaultExchangeHolder.marshal(exchange, false);
baos = new ByteArrayOutputStream(1048600);// 真兇在這里
hessianOut = new Hessian2Output(baos);
hessianOut.startMessage();
hessianOut.writeObject(data);
hessianOut.completeMessage();
hessianOut.flush();
exchangeData = baos.toByteArray();
ByteArrayOutputStream的構(gòu)造方法
public ByteArrayOutputStream(int size) {
if (size < 0) {
throw new IllegalArgumentException("Negative initial size: "
+ size);
}
buf = new byte[size];
}
其實就是在利用Hessian序列化之前, new了一個1M大小的byte數(shù)組,導(dǎo)致了大量的大對象出現(xiàn),而這個byte數(shù)組只是作為一個buf來使用, 而且大小不夠時會自動增長(The buffer automatically grows as data is written to it.),所以根本沒必要設(shè)置那么大.
