记一次生产事故OOM问题排查

背景

线上应用需要进行一个涉及600W数据的操作,之前我们应用从来没有一次性应对这么大量的数据,最多就一次数十万而已。结果,这次600W的数据操作引起了生产事故,直接导致应用不可用长达半小时之久。

OOM

晚上九点半,监控告警提示线上应用宕机。紧急排查发现应用的的进程已经不在了,怀疑是因为内存占用过多导致被操作系统杀进程了。接着查看操作系统日志,如下,果然发现是因为内存占用高达8G而被系统直接杀进程。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[webapp@hd2-cil-rs-app-01 ~]$ dmesg
.
.
.
[38617319.591980] [13605] 0 13605 35957 340 71 0 0 sshd
[38617319.591982] [13607] 10006 13607 35957 361 67 0 0 sshd
[38617319.591984] [13608] 10006 13608 28879 143 14 0 0 bash
[38617319.591986] [14164] 10006 14164 2032213 1048193 2198 0 0 java
[38617319.591988] [14784] 10006 14784 30864 447 18 0 0 htop
[38617319.591989] [14802] 5000 14802 20750 270 38 0 0 zabbix_agentd
[38617319.591991] [14803] 5000 14803 20750 255 38 0 0 zabbix_agentd
[38617319.591993] [14805] 5000 14805 20750 255 38 0 0 zabbix_agentd
[38617319.591994] Out of memory: Kill process 14164 (java) score 258 or sacrifice child
[38617319.594257] Killed process 14164 (java) total-vm:8128852kB, anon-rss:4192624kB, file-rss:148kB, shmem-rss:0kB
1
2
3
4
5
6
7
8
9
10
11
12
[webapp@hd2-cil-rs-app-01 ~]$ sudo vim /var/log/messages
.
.
.
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: [13608] 10006 13608 28879 143 14 0 0 bash
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: [14164] 10006 14164 2032213 1048193 2198 0 0 java
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: [14784] 10006 14784 30864 447 18 0 0 htop
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: [14802] 5000 14802 20750 270 38 0 0 zabbix_agentd
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: [14803] 5000 14803 20750 255 38 0 0 zabbix_agentd
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: [14805] 5000 14805 20750 255 38 0 0 zabbix_agentd
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: Out of memory: Kill process 14164 (java) score 258 or sacrifice child
Apr 21 21:36:40 hd2-cil-rs-app-01 kernel: Killed process 14164 (java) total-vm:8128852kB, anon-rss:4192624kB, file-rss:148kB, shmem-rss:0kB

立即重启应用,并给springboot应用加上内存限制参数,如下,最大允许内存2G,并在OOM时保存内存快照,以及打印GC日志。

1
2
3
4
5
6
7
8
9
10
11
12
13
java -jar 
-server
-Xms1024M
-Xmx2048M
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/opt/neu-marketing-service/current/dump
-XX:+UseGCLogFileRotation
-XX:+PrintGCDateStamps
-Xloggc:/opt/neu-marketing-service/current/gc-%t.log
-XX:+PrintGC
-XX:+UseConcMarkSweepGC
-Dspring.profiles.active=product
neu-marketing.jar

CPU满载

应用重启后,刚开始几分钟很正常,但是很快监控报警CPU占用过高,并且应用很快不再响应外部的任何请求,所有的HTTP请求全部阻塞直到网关超时。

通过top以及htop命令立即定位到CPU占用高的进程正是刚刚重启的应用。然后通过如下命令,来定位java应用是那个线程占用CPU过高:

1
2
3
[webapp@hd2-cil-rs-app-01 current]$ ps -aux | grep marketing
webapp 24161 2.0 11.9 8257484 1941828 ? Sl 4月21 21:41 java -jar -server -Xms1024M -Xmx2048M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/neu-marketing-service/current/dump -Dspring.profiles.active=product -XX:+UseGCLogFileRotation -XX:+PrintGCDateStamps -Xloggc:/opt/neu-marketing-service/current/gc-%t.log -XX:+PrintGC -XX:+UseConcMarkSweepGC neu-marketing.jar
webapp 29709 0.0 0.0 112680 964 pts/4 S+ 10:02 0:00 grep marketing
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
[webapp@hd2-cil-rs-app-01 current]$ ps -mp 24161 -o THREAD,tid,time
USER %CPU PRI SCNT WCHAN USER SYSTEM TID TIME
webapp 200 - - - - - - 00:06:08
webapp 0.0 19 - futex_ - - 24161 00:00:00
webapp 25.3 19 - futex_ - - 24163 00:00:46
webapp 0.8 19 - futex_ - - 24164 00:00:01
webapp 0.9 19 - futex_ - - 24165 00:00:01
webapp 0.8 19 - futex_ - - 24166 00:00:01
webapp 0.9 19 - futex_ - - 24167 00:00:01
webapp 1.9 19 - futex_ - - 24168 00:00:03
webapp 0.7 19 - futex_ - - 24169 00:00:01
webapp 0.0 19 - futex_ - - 24170 00:00:00
webapp 0.0 19 - futex_ - - 24171 00:00:00
webapp 0.0 19 - futex_ - - 24172 00:00:00
webapp 0.0 19 - futex_ - - 24173 00:00:00
webapp 31.7 19 - futex_ - - 24174 00:00:58
webapp 31.4 19 - futex_ - - 24175 00:00:57
.
.
.

发现tid为24174的线程,CPU占用很高,将该tid转为16进制,并通过jstack命令定位该线程。

1
2
[webapp@hd2-cil-rs-app-01 current]$ printf "%x" 24174
5e6e
1
2
[webapp@hd2-cil-rs-app-01 current]$ jstack 24161 | grep 5e6e
"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 tid=0x00007f35ec1c8800 nid=0x5e6e waiting on condition [0x0000000000000000]

根据输出显示,CPU占用高的并不是用户线程,而是JVM的线程,怀疑是不是GC出了问题。

Full GC

接着排查应用的GC日志,一查直接吓一跳,日志显示应用刚启动时GC很正常,但是几分钟后,频繁出现Full GC甚至一个版面全是Full GC。内存泄漏或者内存不足石锤了,接下来定位具体的内存泄漏位置就令人头疼了。好在这时候应用再次发生OOM,并生成了内存快照,可以用来定位内存泄漏位置。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
2020-04-21T21:50:54.730+0800: 1.071: [GC (Allocation Failure)  272640K->4882K(1014528K), 0.0092116 secs]
2020-04-21T21:50:55.188+0800: 1.529: [GC (Allocation Failure) 277522K->8403K(1014528K), 0.0121875 secs]
2020-04-21T21:50:55.552+0800: 1.893: [GC (Allocation Failure) 281043K->10651K(1014528K), 0.0108046 secs]
2020-04-21T21:50:55.865+0800: 2.205: [GC (Allocation Failure) 283291K->13062K(1014528K), 0.0119422 secs]
2020-04-21T21:50:55.879+0800: 2.219: [GC (CMS Initial Mark) 18840K(1014528K), 0.0033580 secs]
2020-04-21T21:50:56.475+0800: 2.816: [GC (CMS Final Remark) 247008K(1014528K), 0.0654906 secs]
2020-04-21T21:50:56.655+0800: 2.995: [GC (Allocation Failure) 285702K->11043K(1014528K), 0.0194478 secs]
2020-04-21T21:50:57.463+0800: 3.803: [GC (Allocation Failure) 283683K->22156K(1014528K), 0.0323949 secs]
2020-04-21T21:50:58.064+0800: 4.405: [GC (Allocation Failure) 294796K->28169K(1014528K), 0.0787791 secs]
2020-04-21T21:50:58.579+0800: 4.920: [GC (Allocation Failure) 300809K->27735K(1014528K), 0.0642011 secs]
2020-04-21T21:50:59.367+0800: 5.708: [GC (Allocation Failure) 300375K->30433K(1014528K), 0.0398394 secs]
2020-04-21T21:50:59.856+0800: 6.197: [GC (Allocation Failure) 303073K->32503K(1014528K), 0.0655292 secs]
.
.
.
2020-04-21T21:54:40.923+0800: 227.263: [Full GC (Allocation Failure) 2063100K->2062655K(2063104K), 1.2139026 secs]
2020-04-21T21:54:42.156+0800: 228.496: [Full GC (Allocation Failure) 2063102K->2062830K(2063104K), 0.8924460 secs]
2020-04-21T21:54:43.057+0800: 229.398: [Full GC (Allocation Failure) 2063099K->2062934K(2063104K), 1.1843272 secs]
2020-04-21T21:54:44.251+0800: 230.592: [Full GC (Allocation Failure) 2063101K->2063000K(2063104K), 0.8979688 secs]
2020-04-21T21:54:45.158+0800: 231.499: [Full GC (Allocation Failure) 2063103K->2063038K(2063104K), 1.1687725 secs]
2020-04-21T21:54:46.339+0800: 232.679: [Full GC (Allocation Failure) 2063103K->2063068K(2063104K), 1.1665188 secs]
2020-04-21T21:54:47.514+0800: 233.855: [Full GC (Allocation Failure) 2063096K->2063088K(2063104K), 1.1507210 secs]
2020-04-21T21:54:48.673+0800: 235.014: [Full GC (Allocation Failure) 2063103K->2063096K(2063104K), 1.2230892 secs]
2020-04-21T21:54:49.902+0800: 236.243: [GC (CMS Initial Mark) 2063102K(2063104K), 0.0594648 secs]
2020-04-21T21:54:50.294+0800: 236.634: [Full GC (Allocation Failure) 2063103K->2063096K(2063104K), 0.8812470 secs]
2020-04-21T21:54:51.183+0800: 237.524: [Full GC (Allocation Failure) 2063096K->2063096K(2063104K), 0.8718934 secs]
2020-04-21T21:54:52.063+0800: 238.404: [Full GC (Allocation Failure) 2063096K->2063004K(2063104K), 1.2422705 secs]

Dump文件分析

下载内存快照到本地分析,内存快照文件非常大达到2.2G,建议压缩后再下载,如下,这次的2.2G大小的内存快照压缩后仅剩95M大小,直接压缩成了原来大小的4%。

1
2
3
4
[webapp@hd2-cil-rs-app-01 current]$ ls -hl
总用量 2.2G
-rw------- 1 webapp webapp 2.1G 4月 21 21:55 dump
-rw-rw-r-- 1 webapp webapp 95M 4月 22 16:48 dump.zip

分析内存快照推荐使用MAT,是eclipse官方推出的本地内存分析工具,下载链接是https://www.eclipse.org/mat/downloads.php

MAT解析内存快照结果如下图,立即分析出来com.mysql.jdbc.JDBC42ResultSet的对象占用了1.2G的内存,从类名可以分析出来这次OOM的罪魁祸首是一次mysql的数据库查询,由于查询结果太多导致内存不足而频繁Full GC乃至最终OOM了。

Leak Suspects

image

通过Leak Suspects,快速分析快照文件,MAT提示有如下两个内存问题:

image

点击第一个问题的Details按钮,发现泄漏的内存引用的对象中,有一个是用户自己创建的定时任务线程,继续查看该线程对象的引用关系,成功定位到发生OOM的方法位置。

image

image

再查看第二个问题,第二个问题直接提供了OOM时的异常栈查看,查看异常栈,轻松定位到OOM的位置。

image

image

最后发现两个问题实际上都指向了同一个位置,即发生OOM的罪魁祸首。这时候就需要对这一处代码进行code review了,从代码层面排查OOM的原因。

Histogram

同样也可以通过内存排行Histogram来定位OOM位置,如下图

image

通过内存排行可见,byte[]占用了1.2G的内存,查看该对象的引用对象内存排行

image

可见byte[]的引用对象中,用户线程schedule-thread-5占用的内存最高,接着查看该对象的引用关系,同样可以定位到内存泄漏的具体位置。

image

image

问题定位

根据MAT定位出来的位置进行code review代码后,发现定时任务定时触发该代码,逻辑为从mysql中查询待处理的记录,但是却没有加上单次查询的数量限制。平时数据量不大,因此这个问题并没有引起任何明显的现象,但是这次涉及600W数据的操作,导致该逻辑需要查询的记录数量直接增长到了百万级别。

结果定时任务一次性从mysql查询读取数百万条记录,应用内存迅速耗尽而触发频繁的Full GC。由于频繁的Full GC,导致应用假死、所有请求阻塞直到网关超时,最终内存不足发生OOM异常。

解决

问题定位分析完毕后,解决就非常简单了,直接给该查询添加上单次查询上限,加个limit限制就解决了这次的OOM问题。

代码迅速上线后,应用立即恢复正常,监控也不再提示任何警告。