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

迷南。 2023-02-13 11:28 17阅读 0赞

## 背景 ##

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

## OOM ##

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

[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

[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日志。

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过高：

[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

[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命令定位该线程。

[webapp@hd2-cil-rs-app-01 current]$ printf "%x" 24174
    5e6e

[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，并生成了内存快照，可以用来定位内存泄漏位置。

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%。

[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][https_www.eclipse.org_mat_downloads.php]。

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

### Leak Suspects ###

![在这里插入图片描述][2020052820094654.png]

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

![在这里插入图片描述][20200528201001556.png]

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

![在这里插入图片描述][2020052820101293.png]

![在这里插入图片描述][20200528201025436.png]

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

![在这里插入图片描述][20200528201036337.png]

![在这里插入图片描述][20200528201043830.png]

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

### Histogram ###

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

![在这里插入图片描述][20200528201057207.png]

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

\[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-6uF2jdBZ-1590667759239)(https://img.wakzz.cn/202004/ThEJ4bQJeA.png)\]

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

![在这里插入图片描述][20200528201104201.png]

![在这里插入图片描述][20200528201111314.png]

## 问题定位 ##

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

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

## 解决 ##

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

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

[https_www.eclipse.org_mat_downloads.php]: https://www.eclipse.org/mat/downloads.php
[2020052820094654.png]: https://img-blog.csdnimg.cn/2020052820094654.png
[20200528201001556.png]: https://img-blog.csdnimg.cn/20200528201001556.png
[2020052820101293.png]: https://img-blog.csdnimg.cn/2020052820101293.png
[20200528201025436.png]: https://img-blog.csdnimg.cn/20200528201025436.png
[20200528201036337.png]: https://img-blog.csdnimg.cn/20200528201036337.png
[20200528201043830.png]: https://img-blog.csdnimg.cn/20200528201043830.png
[20200528201057207.png]: https://img-blog.csdnimg.cn/20200528201057207.png
[20200528201104201.png]: https://img-blog.csdnimg.cn/20200528201104201.png
[20200528201111314.png]: https://img-blog.csdnimg.cn/20200528201111314.png