一次生产系统 Full GC 问题分析与排查总结



转载请注明 AIQ - 最专业的机器学习大数据社区  http://www.6aiq.com

AIQ 机器学习大数据 知乎专栏 点击关注

一次生产系统 Full GC 问题分析与排查总结

背景

最近某线上业务系统生产环境频频 CPU 使用率过低,频繁告警,通过重启可以缓解,但是过了一段时间又会继续预警,线上两个服务节点相继出现 CPU 资源紧张,导致服务器卡死不可用,通过告警信息可以看到以下问题:

从上图可以看到,目前 zabbix 监控展示 CPU 空闲时间已经低于预警线,证明目前 CPU 资源占用过高,考虑到最近并没有特别开发任务上线,但是最近有发布过一个新的营销活动,有可能是因为突然用户量增长进一步凸显该问题。

从 Pinpoint APM 监控工具看到,从 9 月 3 号下午开始,系统开始出现频繁 full gc 的情况,而刚好 9 月 3 号下午发布了一个新活动,基本可以断定这可能是用户量突然激增,凸显潜伏已久的系统问题,于是接下来方向就可以往 full gc 方向去排查,找出引起 full gc 的代码。

侦查思路

往 FULL GC 方向侦查,怀疑存在内存泄露

排查路线:

既然上面已经定位到是 FULL GC 问题,我们就可以用常用 FULL C 的手段去解决。在这次故障分析我们是利用 MAT 去做分析,主要对以下几点做排查:

  • 程序是否内存泄露

  • 程序中是否存在不合理的大对象占用

  • 程序中部分对象产生内存是否可以优化

导出 JVM dump 文件和 jstack 线程日志, 保留案发现场

因为公司不允许个人访问线上服务器,于是让运维同学在服务器出现故障时导出 jvm dump 文件和 jstack 线程日志,如果自己有权限去生产服务器的话,可以通过以下指令导出 jvm dump 文件

jmap -dump:format=b,file=文件名 [服务进程ID]

结合 MAT 分析工具, 找出可疑对象

使用 MAT 前,先简单介绍下 MAT 的一些常用的指标和功能概念:

  • Shallow Heap 指标:对象本身占用内存的大小,不包含对其他对象的引用,也就是对象头加成员变量(不是成员变量的值)的总和

  • Retained Heap 指标:是该对象自己的 shallow size,加上从该对象能直接或间接访问到对象的 shallow size 之和。换句话说,retained size 是该对象被 GC 之后所能回收到内存的总和。

  • Histogram 动作:列出每个类的实例数

  • Dominator Tree 动作:列出最大的对象以及它们保存的内容

  • Top Consumers 动作: 按照类和包分组打印花费最高的实例

  • Duplicate Classes 动作: 检测由多个类加载器加载的类

  • Leak Suspects 报告: 包括泄密嫌疑人和系统概述

  • Top Components 报告:列出大于总堆的 1%的组件的报告

通过 Leak Suspects 排查内存泄露

Ecplise Memory Analyzer导入 JVM dump 文件,点击工具栏上的 Leak Suspects 菜单项来生成内存泄露分析报告,也可以直接点击饼图下方的 Reports->Leak Suspects链接来生成报告。如图:

MAT 工具分析了 heap dump 后在界面上非常直观的展示了一个饼图,该图深色区域被怀疑有内存泄漏,可以发现整个 heap 才 1.5G 内存,深色区域就占了 57.76%。接下来是一个简短的描述,MAT 告诉我们存在两个可疑问题

  • Problem Suspect 1:告诉我们java.lang.Thread线程实例占用了大量内存,一共存在5154个实例,并且明确指出system class loader加载的java.lang.Thread实例占据了643,021,136 (41.03%)字节 ,并建议用关键字 "java.lang.Thread" 进行检查。所以,MAT 通过简单的两句话就说明了问题所在,就算使用者没什么处理内存问题的经验。在下面还有一个 "Details" 链接,MAT 给了一个参考类。如图:

  • Problem Suspect 2: 告诉我们jdk.nashorn.internal.runtime.Context线程实例占用了大量内存, 并且明确指出sun.misc.Launcher$ExtClassLoader @ 0x9000cf78加载的jdk.nashorn.internal.runtime.Context实例占据了262,229,320 (16.73%)字节,并建议用关键字sun.misc.Launcher$ExtClassLoader @ 0x9000cf78 jdk.nashorn.internal.runtime.Context进行检查

通过 Top Consumers 定位大对象

点击 Actions->Top Consumers , 查看大对象有哪些

从上图可以看出,java.lang.Threadjdk.nashorn.*javax.script.*这些类实例占据了大部分内存

问题分析

从上面分析报告,可疑大胆推断以下结论:

  • 大量java.lang.Thread实例,明显不合理是线程使用不合理,怀疑有地方不断创建线程,没有使用线程池导致

  • 大量jdk.nashorn.internal._javax.script._相关实例,而jdk.nashorn.*这个包是 Nashorn JavaScript 引擎的包,主要是 nashorn 用于在 JVM 上以原生方式运行动态的 JavaScript 代码来扩展 Java 的功能,javax.script包用于 javascript 与 java 交互操作。于是可以基本断定这是跟 javascript 脚本相关操作有关,应该是有地方不断创建 javascript 脚本相关对象没有被回收。

结合以上两点,推测应用程序线程和脚本操作部分出现问题,与该系统相关开发人员沟通,确实该系统是有大量 javascript 脚本操作,是通过 Javascript 脚本做一些特性开发,然后在在 java 调用执行。尝试使用包名jdk.nashorn查找运维导出的 jstack 线程日志,看看最接近的业务代码是什么

果然看到了线程日志里面找到了疑似线程操作的业务代码,通过查看源码,一步步查看调用链,发现了有个地方会每次实例初始化都会创建一份脚本引擎

这段代码大概作用是把每个任务的规则脚本存放在脚本引擎,然后存放在threadLocal里,每个MissionEventHandler实例初始化都会创建一个threadLocal用于存放当前线程任务脚本,以防多线程操作同一个MissionEventHandler实例会引起脚本因并发被篡改问题。而经过沿着调用链查看源码了解,这些MissionEventHandler实例只会业务人员点击任务下线的时候才会进行销毁处理,那就是只要任务不下线,这些任务会一直存活在内存中。

但是只要MissionEventHandler实例数量控制好,应该是不会出现上述大量脚本相关实例引发频繁 FULL GC 问题,接下来我们的侦查方向就是查看MissionEventHandler实例创建源头,** 是否系统存在批量创建该实例的代码?** 继续沿着调用链查看源代码,发现了一个异步观察者类,它是用来通知消息事件的,以下是其中一个方法

这里是使用了CompletableFuturesupplyAsync(Supplier supplier)方法进行异步处理,再进一步查看supplyAsync的源码

从上面代码可以看到,supplyAsync有 2 个重载方法,当我们不指定线程池,它默认是调用第一个方法,ForkJoinPool.getCommonPoolParallelism() > 1才会使用 commonPool 线程池,否则该方法默认会每次创建一条新的线程去处理。那有没有可能是ForkJoinPool.getCommonPoolParallelism()<=1导致每次都创建新的线程呢?我们进一步查看ForkJoinPool.getCommonPoolParallelism()源码,发现这方法使用 Java 8 中的ForkJoinPool.commonPool()可以使用一个特殊的 ForkJoinPool。该池使用一个取决于可用内核数量的预设并行度。一般情况下,预设的并行度是CPU 内核数 -1,该系统在生产环境运行的服务器核数为 2,那就是并行度为 1,即这里的ForkJoinPool.getCommonPoolParallelism()=1, 意味着CompletableFuturesupplyAsync方法在这里处理业务是每次都创建一条新的线程去处理

总结

根据上面的分析,一切都真相大白,之前看到的大量java.lang.Thread实例就是因为处理业务时,默认每次都会开启一条新的线程,导致出现大量的线程实例,而这些大量的线程实例又会引发大量的通知消息操作,导致持有的脚本相关实例没法被回收,从而引发了大量jdk.nashorn.internal.*javax.script.*占据堆内存。

解决方案

这里的解决方案很简单,这里引发的问题都是因为没有使用到线程池导致的,可以采取以下两种措施:

  • 通过在 tomcat 配置 jvm 启动参数-Djava.util.concurrent.ForkJoinPool.common.parallelism=2, 可以让supplyAsync(Supplier supplier)方法启动默认的ForkJoinPool.commonPool()去执行

  • 改为调用CompletableFuture supplyAsync(Supplier supplier,Executor executor),给方法指定线程池 (推荐)

在本次改造是使用第二个方案,创建了一个自定义线程池,然后指定线程池去执行操作,修改后代码如下 (高亮部分):

上线后观察监控

上线后通过 PINPOINT 观察,再也没出现 FULL GC 问题,如下图所示:

Java 引用法则说明

从最强到最弱,不同的引用(可到达性)级别反映了对象的生命周期。

  • Strong Ref(强引用):通常我们编写的代码都是 Strong Ref,于此对应的是强可达性,只有去掉强可达,对象才被回收。

  • Soft Ref(软引用):对应软可达性,只要有足够的内存,就一直保持对象,直到发现内存吃紧且没有 Strong Ref 时才回收对象。一般可用来实现缓存,通过 java.lang.ref.SoftReference 类实现。

  • Weak Ref(弱引用):比 Soft Ref 更弱,当发现不存在 Strong Ref 时,立刻回收对象而不必等到内存吃紧的时候。通过 java.lang.ref.WeakReference 和 java.util.WeakHashMap 类实现。

  • Phantom Ref(虚引用):根本不会在内存中保持任何对象,你只能使用 Phantom Ref 本身。一般用于在进入 finalize() 方法后进行特殊的清理过程,通过 java.lang.ref.PhantomReference 实现。

特别鸣谢

这里感谢下我们的架构师大佬啟锵同学,帮助我们一起快速定位问题,不然也不会那么快速可以定位到问题代码


更多高质资源 尽在AIQ 机器学习大数据 知乎专栏 点击关注

转载请注明 AIQ - 最专业的机器学习大数据社区  http://www.6aiq.com