一、问题背景

下午突发服务器CPU频繁撑爆,服务启动后不久就挂掉。一周前系统有一次投产,之后再没有更新过系统。同时在日志中看到大量的dubbo服务调用失败。




java jvm 溢出怎么判断 如何查看jvm内存溢出日志_OOM


二、排查问题产生原因

1.查看JVM崩溃日志hs_err_pid.log

JVM崩溃时会生成hs_err_pid_xxx.log日志文件,记录堆栈信息、线程情况、系统信息等,可以通过-XX:ErrorFile 指定该日志文件输出路径。

首先看日志中的线程情况,存在大量的dubbo线程阻塞:


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_JVM_02


崩溃日志的堆栈部分可以看到GVM堆内存老年代已经达到99%,新生代内存也所剩不多:


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_OOM_03


结合日志中10次垃圾回收情况,可以看到老年代接近满负荷基本无法被回收,在这种情况下年轻代的内存对象无法放入老年代,随着几次YoungGC就会导致堆内存溢出。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_内存溢出_04


结合以上情况基本可以判定是内存溢出导致服务宕机,线程无法释放,将CPU撑爆。

2.代码排查

  1. 排查最近上线代码是否存在以下情况:

死循环:未发现。

慢SQL:经分析dump文件发现一个可疑SQL,只有140万条数据,但查询需要5分钟。

大数据量查询:未发现。

高并发请求:未发现。

  1. 排查下游系统调用是否正常

在日志中发现POST请求异常,但不至于导致系统崩溃,可排除该情况,未发现其他调用三方异常。

3.内存溢出dump文件分析

在JVM参数中配置以下参数 XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath,当内存溢出时输出Dump文件,dump文件名格式为xxx.hprof。

下载Eclipse Memory Analyzer对dump文件进行分析,下载地址:https://www.eclipse.org/mat/previousReleases.php

最新版要求jdk11+,这里我选择1.9.0,可以支持jdk8。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_java jvm 溢出怎么判断_05


打开MAT,File--->open dump file--->选择本次输出的dump文件,可以看到如下总览页面,点击Leak Suspects查看内存泄露分析。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_java jvm 溢出怎么判断_06


进入Leak Suspects可以看到,有2处可疑的内存泄露问题,占用了绝大部分内存,接下来分析这2处问题。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_Powered by 金山文档_07


这里先说一下结论,堆内存总共3.1G,Suspect1问题指向一个慢SQL,间接导致1.7G内存无法回收,Suspect2 由com.mysql.jdbc.ByteArrayRow导致1.2G内存无法回收,原始sql指向与Suspect1同样的慢SQL,这样就基本可以确定是这一条慢SQL导致的内存溢出。

点击Suspect1 details,展示如下页面:

这里很明显地标出了一个业务实体类占用了大量内存,从图片最下方可以看到,该类有116万个对象存活,占用148965Kb内存,100多M也不算多,但看后一项Retained Heap Size是1873201Kb,高达1.7G。

Retained Heap Size是本身占用的内存+间接引用的对象的大小,JVM垃圾回收是当对象不再被引用时才能会回收,那么很明显这个业务实体类间接导致1.7G内存无法回收。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_JVM_08


然后继续往下看,Tread Stack线程栈部分,明确地给出了该业务实体类代码位置,在一个Service方法中该实体类作为返回值列表返回,同时该Service方法的底层就是调用上面提到的慢SQL。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_Powered by 金山文档_09


回到Leak Suspect页面,点击Suspect2---》details,查看第二个疑似泄漏点。

从支配树 Dominator Tree可以看到,问题指向Mybatis SQL执行,但从这里看不到问题的源头。

接下来看Shortest Paths To the Accumulation Point(应该是最近接GC Root的聚集点),这里有一个JDBC4PrepareStatement,很明显这是预处理SQL,点击左侧栏Attribute-originalSql,可以看到这里有一个select语句,与Suspect1中的慢SQL相同。


java jvm 溢出怎么判断 如何查看jvm内存溢出日志_内存溢出_10


4.问题原因定位

最终定位到问题原因是慢SQL导致内存无法回收,然后导致线程阻塞,CPU被撑爆。

但仍有一个疑点,如果是慢SQL问题为什么一周之后才爆发?

经排查是因为一笔特殊业务传参不全,导致SQL查询缺少条件,就变成慢SQL了。但一百多万调数据查询几分钟仍不合理。

根据排查情况来看,当出现内存溢出时,业务日志基本上无法用于定位问题根源,因为系统崩溃连锁反应会阻塞所有线程和数据库SQL执行,无法从海量的报错里找出引发崩溃的源头。

建议先排查GC日志和线程情况,确定内存溢出问题的话,直接拿dump文件分析问题源头,同时复盘最近提交的代码是否存在可疑的内存泄露。不过根据这次排查发现导致问题的原因并不是最近提交的代码,所以还是建议优先分析dump文件定位泄露源。

三、解决方案

1.由于该慢SQL并非正常业务产生,所以要在业务层进行限制,保证按正常查询条件执行。

2.解决慢SQL查询问题,杜绝之后出现类似情况。