一次非典型的CPU告警的排查
最近线上频繁收到CPU超过阈值的告警, 很明显是哪里出了问题. 因而排查了一番, 到最后找到罪魁祸首的时候, 忽然意识到此次是一次颇有意思的"非典型"的CPU的问题, 因此这里特地记录一下.java
为啥说它是非典型呢, 由于在个人经验里, 典型的CPU飙升一般都是业务代码里面有死循环, 或是某个RPC性能太低阻塞了大量线程等等, 而此次的CPU问题倒是由GC引发的, 因吹斯汀linux
来看看排查过程apache
找出占用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是咱们对应的java进程的进程ID, sed -n "7,17p" 是取第7到第17行, 由于前7行都是top命令的头部信息, 因此第7到第17行就是该线程下最耗CPU的前10个线程了.bash
其中第一列的"pid"就是JVM里面对应的线程ID, 咱们只须要用线程ID在jstack里面找到对应的线程就知道是谁在搞鬼了.app
不过需注意的是top命令中的PID是十进制的, 而jstack里面的线程ID是十六进制的, 因此咱们还须要作一个工做, 就是把上面的PID转成十六进制, 这里我只转换了最耗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
如今咱们已经知道消耗CPU的线程ID, 接着就要去看看这些线程ID对应的是什么线程.性能
首先使用jstack打出JVM里面的全部的线程信息:spa
[app@linux-v-l-02:/app/tmp/]jstack -l $pid >>/tmp/jstack.txt
复制代码
值得一提的是, 因为JVM里面的线程一直在变化, 而TOP中的线程也一直在变化, 因此若是jstack命令和top命令是分开执行的话, 颇有可能二者的线程ID会对应不上. 所以top命令和jstack命令最好是写好脚本一块儿执行. 其实我就是写脚本一块儿执行的~命令行
接着, 看看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就是对应的十六进制的线程ID. 从jstack能够看出, 竟然最耗CPU的线程都是一些GC线程.
对JVM的FULL GC咱们是有监控的, 这个应用自从换了G1以后, 通常一周左右才会发生一次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个问题:
- 出现了mixed类型的Evacuation Pause
- 频繁G1 Humongous Allocation致使的to-space exhausted, 说明大量的大对象不断地分配出来
- GC pause时间达到0.3849037 secs, 这是咱们最不可容忍的
另外还有一个更严重的问题这里是看不出来的, 就是相似的日志很是频繁! 高峰时期基本就是每2秒钟打印出一次
jmap -histo
经过上面的GC日志, 咱们基本能够判断, 是应用程序不断地new一些大对象致使的.
那什么是大对象呢?
通常状况就是局部变量的List, 一般能够经过jmap -histo来查看堆内哪些对象占用内存比较大, 实例数是多少
因此, 先经过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
....
复制代码
通常来讲, 若是运气好, 并且业务代码有问题的, 一般能在jmap -histo里面看到咱们业务涉及到的类名的.
可是很惋惜, 这里没有.
然而, 聪明的同窗可能一眼就看出了这个堆实际上是颇有问题的.
咱们看排行第一的[B (byte数组), 占用了堆大小1032796420(1G左右), 而instances却只有1120多个, 简单地一相除, 竟然每一个对象能有1M大小!
很明显, 这就是咱们要找的大对象了, 可是只知道是一些byte数组, 并不知道是什么数组, 因此还须要进一步排查
为何1M就是大对象了呢? 因为咱们的堆只有4G大小, 通常G1最大只有2048个region, 所以每一个region的大小就是2M. G1在分配新生代的对象的内存空间时, 发现这个对象大于region size的一半, 就能够认为是大对象了,故而发生G1 Humongous Allocation
jmap -dump:format=b
使用jmap -dump:format=b,file=head.hprof $pid 命令能够把JVM的堆内容dump出来. dump出来后通常直接在命令行查看是看不出什么的, 得下载到本地, 借助一些分析工具来进行分析. 能够有不少工具能够分析, 例如jvisualvm, jprofile, MAT等等
这里我用到的是jvisualvm, 打开jvisualvm==>文件==>装入==>选中我刚刚下载下来的head.hprof, 而后再点击"类", 再点击按大小排序, 能够获得以下图.
能够看出, 堆里面的byte数组实例数占比只有0.9%, 内存大小占比却高达30%, 说明每个实例都是大对象.
接下来咱们双击第一行的"byte[]" 查看这些byte数组的明细. 能够看不少的对象都是1048600byte, 也就是恰好1M, 不过这样仍是看不出这个数组的内容, 因此咱们导出这个数组到本地, 以下图:
导出后先用Sublime Text打开看一下, 以下图
虽然还没法肯定这个数组是什么代码产生的, 可是至少能够大概肯定了问题产生的缘由: 确定是某处代码new了一个1048600大的byte数组,而实际场景中这个byte数组只须要1k左右便可,后面没有填充的位都是默认的0值
最后证明一下咱们的猜想,简单的用
String str= new String (bytearr, "UTF-8");
System.out.println("str = [" + str + "]");
复制代码
把数组内容打印出来, 打印结果大概以下(我省略了大部份内容):
str = [p C0+org.apache.camel.impl.DefaultExchangeHolder�
exchangeId inFaultFlag outFaultFlag exceptioninBodyoutBody inHeaders
outHeaders
remoteOptRolefaceUrlversionfromIfromUser failFaceUrl
.....
复制代码
再用相关的关键词搜索一下代码,最后找出了真凶:
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的构造方法
public ByteArrayOutputStream(int size) {
if (size < 0) {
throw new IllegalArgumentException("Negative initial size: "
+ size);
}
buf = new byte[size];
}
复制代码
其实就是在利用Hessian序列化以前, new了一个1M大小的byte数组,致使了大量的大对象出现,而这个byte数组只是做为一个buf来使用, 并且大小不够时会自动增加(The buffer automatically grows as data is written to it.),因此根本不必设置那么大.
相关文章
- 1. 一次quartz非典型异常排查记录
- 2. Spring源码阅读——记录一次非典型异常排查
- 3. 记一次典型的故障排错
- 4. 记一次CPU太高排查过程
- 5. CPU高的排查
- 6. 一次__libc_message的排查
- 7. 记一次golang程序CPU高的排查过程
- 8. 一次线上CPU高的问题排查实践
- 9. 记一次cpu指标异常的跟踪排查
- 10. 记一次线上CPU持续飙升的问题排查
- 更多相关文章...
- • 一对一关联查询 - MyBatis教程
- • Hibernate的一级缓存 - Hibernate教程
- • 漫谈MySQL的锁机制
- • 互联网组织的未来：剖析GitHub员工的任性之源
相关标签/搜索
每日一句
-
每一个你不满意的现在，都有一个你没有努力的曾经。
最新文章
- 1. Duang!超快Wi-Fi来袭
- 2. 机器学习-补充03 神经网络之**函数(Activation Function)
- 3. git上开源maven项目部署 多module maven项目（多module maven+redis+tomcat+mysql）后台部署流程学习记录
- 4. ecliple-tomcat部署maven项目方式之一
- 5. eclipse新导入的项目经常可以看到“XX cannot be resolved to a type”的报错信息
- 6. Spark RDD的依赖于DAG的工作原理
- 7. VMware安装CentOS-8教程详解
- 8. YDOOK：Java 项目 Spring 项目导入基本四大 jar 包 导入依赖，怎样在 IDEA 的项目结构中导入 jar 包 导入依赖
- 9. 简单方法使得putty（windows10上）可以免密登录树莓派
- 10. idea怎么用本地maven
欢迎关注本站公众号,获取更多信息
相关文章
- 1. 一次quartz非典型异常排查记录
- 2. Spring源码阅读——记录一次非典型异常排查
- 3. 记一次典型的故障排错
- 4. 记一次CPU太高排查过程
- 5. CPU高的排查
- 6. 一次__libc_message的排查
- 7. 记一次golang程序CPU高的排查过程
- 8. 一次线上CPU高的问题排查实践
- 9. 记一次cpu指标异常的跟踪排查
- 10. 记一次线上CPU持续飙升的问题排查