V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
bryan31
V2EX  ›  Java

记一次公司 JVM 堆溢出抽丝剥茧定位的过程

  •  4
     
  •   bryan31 · 2020-08-26 11:10:29 +08:00 · 4979 次点击
    这是一个创建于 1529 天前的主题,其中的信息可能已经有所发展或是发生改变。

    背景

    公司线上有个 tomcat 服务,里面合并部署了大概 8 个微服务,之所以没有像其他微服务那样单独部署,其目的是为了节约服务器资源,况且这 8 个服务是属于边缘服务,并发不高,就算宕机也不会影响核心业务。

    因为并发不高,所以线上一共部署了 2 个 tomcat 进行负载均衡。

    这个 tomcat 刚上生产线,运行挺平稳。大概过了大概 1 天后,运维同事反映 2 个 tomcat 节点均挂了。无法接受新的请求了。CPU 飙升到 100%。

    排查过程一

    接手这个问题后。首先大致看了下当时的 JVM 监控。

    CPU 的确居高不下

    1

    FULL GC 从大概这个小时的 22 分开始,就开始频繁的进行 FULL GC,一分钟最高能进行 10 次 FULL GC

    2

    minor GC 每分钟竟然接近 60 次,相当于每秒钟都有 minor GC

    3

    从老年代的使用情况也反应了这一点

    4

    随机对线上应用分析了线程的 cpu 占用情况,用 top -H -p pid 命令

    5

    可以看到前面 4 条线程,都占用了大量的 CPU 资源。随即进行了 jstack,把线程栈信息拉下来,用前面 4 条线程的 ID 转换 16 进制后进行搜索。发现并没有找到相应的线程。所以判断为不是应用线程导致的。

    第一个结论

    通过对当时 JVM 的的监控情况,可以发现。这个小时的 22 分之前,系统 一直保持着一个比较稳定的运行状态,堆的使用率不高,但是 22 分之后,年轻代大量的 minor gc 后,老年代在几分钟之内被快速的填满。导致了 FULL GC 。同时 FULL GC 不停的发生,导致了大量的 STW,CPU 被 FULL GC 线程占据,出现 CPU 飙高,应用线程由于 STW 再加上 CPU 过高,大量线程被阻塞。同时新的请求又不停的进来,最终 tomcat 的线程池被占满,再也无法响应新的请求了。这个雪球终于还是滚大了。

    分析完了案发现场。要解决的问题变成了:

    是什么原因导致老年代被快速的填满?

    拉了下当时的 JVM 参数

    -Djava.awt.headless=true -Dfile.encoding=UTF-8 -server -Xms2048m -Xmx4096m -Xmn2048m -Xss512k -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+DisableExx plicitGC -XX:MaxTenuringThreshold=5 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection
    -XX:+PrintGCDetails -Xloggc:/data/logs/gc.log

    总共 4 个 G 的堆,年轻代单独给了 2 个 G,按照比率算,JVM 内存各个区的分配情况如下:

    6

    所以开始怀疑是 JVM 参数设置的有问题导致的老年代被快速的占满。

    但是其实这参数已经是之前优化后的结果了,eden 区设置的挺大,大部分我们的方法产生的对象都是朝生夕死的对象,应该大部分都在年轻代会清理了。存活的对象才会进入 survivor 区。到达年龄或者触发了进入老年代的条件后才会进入老年代。基本上老年代里的对象大部分应该是一直存活的对象。比如 static 修饰的对象啊,一直被引用的 缓存啊,spring 容器中的 bean 等等。

    我看了下垃圾回收进入老年代的触发条件后(关注公众号后回复“JVM”获取 JVM 内存分配和回收机制的资料),发现这个场景应该是属于大对象直接进老年代的这种,也就是说年轻代进行 minor GC 后,存活的对象足够大,不足以在 survivor 区域放下了,就直接进入老年代了。

    但是一次 minor GC 应该超过 90%的对象都是无引用对象,只有少部分的对象才是存活的。而且这些个服务的并发一直不高,为什么一次 minor GC 后有那么大量的数据会存活呢。

    随即看了下当时的 jmap -histo 命令产生的文件

    7

    发现 String 这个这个对象的示例竟然有 9000 多 w 个,占用堆超过 2G 。这肯定有问题。但是 tomcat 里有 8 个应用 ,不可能通过分析代码来定位到。还是要从 JVM 入手来反推。

    第二次结论

    程序并发不高,但是在几分钟之内,在 eden 区产生了大量的对象,并且这些对象无法被 minor GC 回收 ,由于太大,触发了大对象直接进老年代机制,老年代会迅速填满,导致 FULL GC,和后面 CPU 的飙升,从而导致 tomcat 的宕机。

    基本判断是,JVM 参数应该没有问题,很可能问题出在应用本身不断产生无法被回收的对象上面。但是我暂时定位不到具体的代码位置。

    排查过程二

    第二天,又看了下当时的 JVM 监控,发现有这么一个监控数据当时漏看了

    8

    这是 FULL GC 之后,老年代的使用率。可以看到。FULL GC 后,老年代依然占据 80%多的空间。full gc 就根本清理不掉老年代的对象。这说明,老年代里的这些对象都是被程序引用着的。所以清理不掉。但是平稳的时候,老年代一直维持着大概 300M 的堆。从这个小时的 22 分开始,之后就狂飙到接近 2G 。这肯定不正常。更加印证了我前面一个观点。这是因为应用程序产生的无法回收的对象导致的。

    但是当时我并没有 dump 下来 jvm 的堆。所以只能等再次重现问题。

    终于,在晚上 9 点多,这个问题又重现了,熟悉的配方,熟悉的味道。

    直接 jmap -dump,经过漫长的等待,产生了 4.2G 的一个堆快照文件 dump.hprof,经过压缩,得到一个 466M 的 tar.gz 文件

    然后 download 到本地,解压。

    运行堆分析工具 JProfile,装载这个 dump.hprof 文件。

    然后查看堆当时的所有类占比大小的信息

    9

    发现导致堆溢出,就是这个 String 对象,和之前 Jmap 得出的结果一样,超过了 2 个 G,并且无法被回收

    随即看大对象视图,发现这些个 String 对象都是被 java.util.ArrayList 引用着的,也就是有一个 ArrayList 里,引用了超过 2G 的对象

    10

    然后查看引用的关系图,往上溯源,源头终于显形:

    11

    这个 ArrayList 是被一个线程栈引用着,而这个线程栈信息里面,可以直接定位到相应的服务,相应的类。具体服务是 Media 这个微服务。

    看来已经要逼近真相了!

    第三次结论

    本次大量频繁的 FULL GC 是因为应用程序产生了大量无法被回收的数据,最终进入老年代,最终把老年代撑满了导致的。具体的定位通过 JVM 的 dump 文件已经分析出,指向了 Media 这个服务的 ImageCombineUtils.getComputedLines 这个方法,是什么会产生尚不知道,需要具体分析代码。

    最后

    得知了具体的代码位置, 直接进去看。经过小伙伴提醒,发现这个代码有一个问题。

    这段代码为一个拆词方法,具体代码就不贴了,里面有一个循环,每一次循环会往一个 ArrayList 里加一个 String 对象,在循环的某一个阶段,会重置循环计数器 i,在普通的参数下并没有问题。但是某些特定的条件下。就会不停的重置循环计数器 i,导致一个死循环。

    以下是模拟出来的结果,可以看到,才运行了一会,这个 ArrayList 就产生了 322w 个对象,且大部分 Stirng 对象都是空值。

    12

    至此,水落石出。

    最终结论

    因为 Media 这个微服务的程序在某一些特殊场景下的一段程序导致了死循环,产生了一个超大的 ArrayList 。导致了年轻代的快速被填满,然后触发了大对象直接进老年代的机制,直接往老年代里面放。老年代被放满之后。触发 FULL GC 。但是这些 ArrayList 被 GC ROOT 根引用着,无法回收。导致回收不掉。老年代依旧满的,随机马上又触发 FULL GC 。同时因为老年代无法被回收,导致 minor GC 也没法清理,不停的进行 minor GC 。大量 GC 导致 STW 和 CPU 飙升,导致应用线程卡顿,阻塞,直至最后整个服务无法接受请求。

    关注作者

    觉得有用的话,请关注下我的公众号「元人部落」,作者坚持原创的内容技术分享,也有开源作品,欢迎关注

    开源仓库为: https://gitee.com/bryan31

    公众号一般周更,每次会分享一些实用的技术,陪你一起成长

    关注后回复“资料”领取 50G 的视频资料,包括一套企业级微服务的视频教学

    img

    29 条回复    2020-09-29 02:19:56 +08:00
    zhuawadao
        1
    zhuawadao  
       2020-08-26 11:25:23 +08:00
    多乎哉?不多矣。关之。
    putaozhenhaochi
        2
    putaozhenhaochi  
       2020-08-26 11:47:27 +08:00 via Android   ❤️ 1
    发推广区。谢谢
    lewis89
        3
    lewis89  
       2020-08-26 11:57:21 +08:00
    写这种代码的直接打死吧,service 所有变量的引用 只在栈上,调用完了 自动弹出 自然就不会被 GCRoot 引用,而且微服务也通常不需要将 引用部署到类的成员变量上面,这样的话 服务本身就是存在状态的,而通常服务都是要被设计成无状态,可以随时被替换 被重启的。
    bl
        4
    bl  
       2020-08-26 11:59:40 +08:00
    可以转载到 upupor.com
    bryan31
        5
    bryan31  
    OP
       2020-08-26 12:07:09 +08:00
    @bl 注明出处,可以转载
    yeqizhang
        6
    yeqizhang  
       2020-08-26 12:13:45 +08:00 via Android
    我记得我之前写的一个 bug 导致死循环,好像运维直接 jstack 直接定位了方法的……这么复杂的吗
    li24361
        7
    li24361  
       2020-08-26 12:14:11 +08:00
    看到 cpu 占满 就应该猜到死循环了,果然

    还有一个可能就是 hashmap 多线程使用不当,

    直接 dump 下来, 看下位置就 ok

    ata 上解决问题的,有一半都是因为这俩原因,已经快跟空指针排查一样慢慢开发都开始学会了
    cheng6563
        8
    cheng6563  
       2020-08-26 12:20:56 +08:00 via Android
    有产生 oom 异常吗? 一般都会设置 oom 时直接强停进程的。
    594duck
        9
    594duck  
       2020-08-26 14:09:22 +08:00
    @cheng6563 他的 JAVA 都写死了自己的内存使用。话说,不会有人不写内存分配就直接开 JAVA 吧。
    bl
        10
    bl  
       2020-08-26 14:28:27 +08:00
    @bryan31
    wakzz
        11
    wakzz  
       2020-08-26 14:49:29 +08:00
    看到 JVM 的 CPU 占用率 100%,要么是 OOM 导致 Full GC,要么是 CPU 循环空载。
    下一步就应该看 gc 日志,以及打印高 CPU 的线程名称来定位是 OOM 导致的 Full GC 还是空载问题。
    定位出 OOM 后,先 jmap 把内存快照生成出来后,重启应用暂时恢复服务,再分析内存快照定位内存泄漏的代码;
    如果是 CPU 空载,则要么 jstack 或者用红火图来定位 CPU 占用多的代码,来定位导致空载的代码。
    haosamax
        12
    haosamax  
       2020-08-26 16:20:31 +08:00
    这个 list 在方法结束后不能回收吗
    x66
        13
    x66  
       2020-08-26 16:39:13 +08:00
    @haosamax 死循环了,for 跳不出去,一直在往 list 里面插入空字符串.
    haosamax
        14
    haosamax  
       2020-08-26 16:40:21 +08:00
    @x66 哦哦,明白了
    x66
        15
    x66  
       2020-08-26 16:40:34 +08:00
    写得不错,关注了!
    bryan31
        16
    bryan31  
    OP
       2020-08-26 16:40:35 +08:00
    @haosamax 这个 list 是程序中是一个几千万次的循环,所以短时间内不会被 gc 回收,最终会进入老年代。在多线程情况下,会触发老年代大量的 full gc
    haosamax
        17
    haosamax  
       2020-08-26 16:46:09 +08:00
    @bryan31 恩恩。好奇的是,现在生产上 G1 有大量使用吗
    bryan31
        18
    bryan31  
    OP
       2020-08-26 16:54:17 +08:00
    @haosamax CMS 其一,CMS 在小内存应用上的表现要优于 G1,而大内存应用上 G1 更有优势,大小内存的界限是 6GB 到 8GB,我司大多数项目堆都在 2~4G 。其二,目前我司用的还是 java8,java8 的 g1 个人认为可能还不成熟。
    haosamax
        19
    haosamax  
       2020-08-26 17:01:53 +08:00
    @bryan31 感谢,学习了!
    securityCoding
        20
    securityCoding  
       2020-08-26 17:27:03 +08:00
    hprof+jstack 一般的问题都能定位到了
    terry0314
        21
    terry0314  
       2020-08-26 17:31:07 +08:00
    好熟悉的报表,是 CAT 吗
    bryan31
        22
    bryan31  
    OP
       2020-08-26 17:32:13 +08:00
    @terry0314 你答对了
    vate32
        23
    vate32  
       2020-08-26 19:25:53 +08:00
    作为一个刚毕业一年的小菜鸡,想了想不知道俺啥时候能达到这种水平
    mazyi
        24
    mazyi  
       2020-08-26 21:20:21 +08:00
    JVM 归根结底还是堆栈信息,出了这种问题第一件事就是要运维搞下来。
    rockyou12
        25
    rockyou12  
       2020-08-26 21:27:53 +08:00
    上次也遇到个类似问题,不过是 sql 拼接有问题导致一条查出来就有 2 个 G,查几次就 oom 了。其实这种问题只要遇到过一次,知道要 heap dump 下来分析,还是不太难。
    bryan31
        26
    bryan31  
    OP
       2020-08-26 22:25:38 +08:00
    @vate32 被虐多了,自然就知道了。你也可以的
    xomix
        27
    xomix  
       2020-08-27 10:05:32 +08:00
    同样的问题在当年做 VB.NET 的时候遇到过,但是当时在开发组内测的时候就发现在一些功能执行后内存会虚增 8MB 不被回收,两个人利用 VS 的调试工具抽了大概 3 小时左右定位问题,没让这种 bug 跑出开发组。

    上线前还是要在开发组内部做一下测试,防止这种恶行 bug 导致生产环境损失。
    xxdd
        28
    xxdd  
       2020-08-27 10:33:58 +08:00
    @Livid 直接删掉吧
    xixinimei
        29
    xixinimei  
       2020-09-29 02:19:56 +08:00
    早先定位 hadoop mapreduce 程序时,也是先 dump 出文件,不过用的是 Eclipse Memory Analyzer 分析的
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   1067 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 22ms · UTC 19:40 · PVG 03:40 · LAX 12:40 · JFK 15:40
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.