GC优化--老年代使用率过高、Full GC之后老年代使用率仍大于60%、log4j2导致内存泄露等问题排查

1 背景

对于 GC 优化，之前一直是小白一个，纯理论玩家，最近刚好线上服务频繁报警：Full GC 之后老年代使用率仍大于 60%，需要进行问题排查，遂记录一下从理论到实践的过程。

线上监控情况如下：

线上配置整个 Java 堆的大小是 4G，可以看到老年代的大小已经占了 3G 左右，并且两次 Full GC 后只回收了 500M 左右的内存空间，这显然是不正常的。

2 目标

定性目标：

1. 降低 Old Gen 使用率；
2. Full GC 后降低 Old Gen 使用率。

3 行动

3.1 确定线上服务进程id

进行 GC 优化的第一步，便是在服务器上找到应用程序运行的进程 id。这里有两个关键信息：

1. 线上服务器基本都是 Linux 操作系统，这意味着它支持多用户、多任务；
2. 你的应用程序属于 Java 应用。

首先，由于不确定应用程序属于哪个用户，因此推荐使用 ps -ef | grep "java" 命令找到所有与 Java 相关的进程，再做进一步判断。一般来说，这个命令足矣直接找到应用程序的进程 id 了。

根据相关信息判断进程 id 为 236097 就是要找的应用程序了。

除了这个命令之外，我再推荐几个命令：

• lsof（查看你的应用程序使用了哪些端口，由端口号可以定位到相关进程）
• jps

关于这两个命令的详细使用，不再赘述。这里只说一下使用 jps 时需要注意的地方。

第一点，jps 命令只能查看当前用户下运行的所有 java 进程。由上图可知应用程序属于 sankuai 这个用户下，因此我在 donghengyi 这个用户下运行 jps 命令是找不到相关 Java 进程的。

第二点，jps 有时会失效。在定位问题的过程中有时会遇到这样一种情况，用 jps 查看不到进程 id，用 ps -ef | grep "java" 却能看到启动的 java 进程。

要解释这种现象，需要了解下 jps 的实现机制：java 程序启动后，会在目录 /tmp/hsperfdata_{userName}/ 下生成几个文件，文件名就是 java 进程的 pid，因此 jps 列出进程 id 就是把这个目录下的文件名列一下而已，至于系统参数，则是读取文件中的内容。如果由于磁盘满了，无法创建这些文件，或者用户对这些文件没有读的权限，又或者因为某种原因这些文件或者目录被清除，就会导致 jps 命令失效。

3.2 查看当前JVM运行参数

找到应用程序进程后要做的第一件事是什么？当然是查看当前 JVM 运行时所用的参数了。相关命令如下：

• jinfo -flags pid：查询 JVM 运行时所有配置参数信息（默认 + 人工设置）；
• jinfo -flag name pid：查询具体参数信息，如 jinfo -flag UseSerialGC pid，查看是否启用 UseSerialGC

对了，使用 jinfo 以及等下讲到的一些 jmap、jstat 等命令，可能会出现上述图片中显示的问题，阅读 Caused by 提供的信息大概可以知道应该是使用的命令版本与 JVM 实际版本不匹配所造成的，解决方案可以参考这篇文章：sun.jvm.hotspot.runtime.VMVersionMismatchException: 虚拟机版本不匹配异常 解决方法。

既然知道是使用的 java 命令版本与运行的 JVM 版本不匹配所造成的问题，那么就先来看看当前使用的 java 命令其所在的目录，说不定会有新的发现。使用 which 命令：

关于 which 命令不做介绍。不出所料，当前服务器上存在多个 java 版本，查看当前 java 命令所使用的版本。使用 java -version 命令：

可知 java 命令所属的 JDK 版本是 1.7，联想到应用程序所使用的 JDK 版本是 1.8，因此出现这个问题便也不稀奇了。

知道了问题发生的原因后，那解决方式便非常多样了，考虑是正在运行的线上服务，这里选择风险最小的方式：安装 JDK8，使用 JDK 相关命令时指定路径。

好了，JVM 运行时的参数已经获取到了，如下：

Non-default VM flags: -XX:CICompilerCount=4 -XX:ConcGCThreads=1 -XX:ErrorFile=null -XX:G1HeapRegionSize=2097152 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null -XX:InitialHeapSize=4294967296 -XX:MarkStackSize=4194304 -XX:MaxGCPauseMillis=100 -XX:MaxHeapSize=4294967296 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=2575302656 -XX:MinHeapDeltaBytes=2097152 -XX:+PrintAdaptiveSizePolicy -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintStringTableStatistics -XX:+PrintTenuringDistribution -XX:StringTableSize=49999 -XX:+TieredCompilation -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC
Command line:  -Dfile.encoding=UTF-8 -Dsun.jnu.encoding=UTF-8 -Djava.net.preferIPv6Addresses=false -Djava.io.tmpdir=/tmp -Djetty.defaultsDescriptor=WEB-INF/web.xml -Duser.timezone=GMT+08 -Xloggc:/var/sankuai/logs/com.sankuai.sjst.m.bdop.gc.log.202007291725 -XX:ErrorFile=/var/sankuai/logs/com.sankuai.sjst.m.bdop.vmerr.log.202007291725 -XX:HeapDumpPath=/var/sankuai/logs/com.sankuai.sjst.m.bdop.heaperr.log.202007291725 -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Denvironment=test -Dmedis_environment=test -Dcore.zookeeper=sgconfig-zk.sankuai.com:9331 -Dapp.key=com.sankuai.sjst.m.bdop -Djetty.appkey=com.sankuai.sjst.m.bdop -Dapp.host=set-gh-sjst-m-bdop02 -Djetty.host=set-gh-sjst-m-bdop02 -Dapp.ip=10.21.197.152 -Dapp.port=8418 -Djetty.port=8418 -Dapp.context=/ -Djetty.context=/ -Dapp.workdir=/opt/meituan/apps/bdop-web/work -Dapp.logdir=/var/sankuai/logs -Djetty.logs=/var/sankuai/logs -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -XX:+UseG1GC -Xmx4g -Xms4g -XX:G1HeapRegionSize=2M -XX:MaxGCPauseMillis=100 -XX:MaxMetaspaceSize=512M -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintCommandLineFlags -XX:+PrintAdaptiveSizePolicy -XX:+PrintStringTableStatistics -XX:+PrintFlagsFinal -XX:StringTableSize=49999 -XX:+TieredCompilation -XX:CICompilerCount=4 -Djetty.webroot=/opt/meituan/apps/bdop-web/work

JVM 中每个参数对应的具体含义、功能以及相关设置不再赘述，有兴趣的可以阅读这篇文章：Java JVM 参数设置大全。

这里重点做下参数解读：

• "Non-default VM flags" 表示 JVM 默认参数，Command line 表示人工配置参数；
• JVM 参数类型分为 Boolean 类型 XX 参数（公式：-XX:+某个属性值 或者 -XX:-某个属性值（+ 表示开启，- 表示关闭））以及 kv 类型 XX 参数（公式：-XX: key=value）；
• -Xms 和 -Xmx 两个经典参数看起既不像 Boolean 类型 XX 参数，也不像 kv 类型 XX 参数。那为什么 -Xms 和 -Xmx 又属于 XX 参数？
  • -Xms = -XX:InitialHeapSize，-Xmx = -XX:MaxHeapSize
  • 一般 -Xms、-Xmx 两个参数会配置相同的值（优点：能够在 Java 垃圾回收机制清理完堆区后不需要重新调整堆区的大小而浪费资源）

考虑这次行动的背景，以及不同垃圾收集器间不同的特性，首先需要确定的便是当前 JVM 所使用的垃圾收集器版本，通过查看获取到的 JVM 参数：-XX:+UseG1GC，可知使用的是 G1 收集器。

如果你对 G1 收集器并不了解，可以先阅读一下这篇文章：JVM--浅谈G1收集器。

3.3 监控当前GC实时信息

在明确了 JVM 所使用的垃圾收集器之后，就需要对当前 GC 运行的情况做一个了解。JDK 提供 jstat -gcutil pid time(ms) 命令监控当前 GC 实时信息。

由于目前问题已修复，因此上图展示的 GC 实时信息（每秒采样一次）已不具参考价值（所以说平时在解决问题的时候，要养成保留现场的习惯，方便以后复盘或者记录使用），这里主要说一下每列所代表的含义。

• S0：年轻代中第一个 survivor（幸存区）使用比例
• S1：年轻代中第二个 survivor（幸存区）使用比例
• E：年轻代中 Eden（伊甸园区）使用比例
• O：老年代使用比例
• M：元数据区使用比例
• $\color{red}{CCS：压缩使用比例（不太了解是干什么的）}$
• YGC：从应用程序启动到采样时 Young GC 次数
• YGCT：从应用程序启动到采样时 Young GC 所用时间(s)
• FGC：从应用程序启动到采样时 Full GC 次数
• FGCT：从应用程序启动到采样时 Full GC 所用时间(s)
• GCT：从应用程序启动到采样时 GC 用的总时间(s)

虽然上面的监控信息和咱们要解决的问题已经没有了关联，但这里存在三个问题：不知道大家有没有注意到监控信息中的 S0 列恒为 0，S1 列恒为 100 这个现象（问题一）？其实除了这个现象之外，当时在排查问题的过程中，还有两个现象同样让我疑惑：

1. 应用程序并没有触发 Full GC，但老年代的使用比例会稍微变小（问题二）；
2. 线上监控显示，虽然老年代与年轻代的内存大小之和等于 4G，符合 JVM 的参数配置，但是老年代的大小和年轻代的大小却并不固定，会随着 GC 的发生而动态改变（问题三）。

其实这三个问题都和 G1 收集器相关，如果你认真阅读了上面介绍 G1 收集器的那篇文章，应该自己就能得出后两个问题的答案。而对于第一个问题，也不必过于纠结，可以参考阅读这篇帖子：gc-s1-always-used-100-never-less-than-100。

3.4 猜想

当初在分析 GC 实时监控信息的过程中，有如下现象：

1. Young GC 正常，年轻代有正常使用；
2. 老年代的使用比例只是单纯维持在一个较高的状态上，并没有出现 MIXGC 后老年代使用比例又疯狂上涨的现象；
3. 每次 MIXGC 后只能降低一点点的老年代使用比例；
4. Full GC 并不频繁（事实上按理说每天有超过两次 Full GC，就要考虑 GC 优化了），并没有出现短时间内疯狂 Full GC 的现象。

结合线上监控信息：Full GC 之后并没有回收掉多少老年代的内存。这是我们对当前 GC 情况的一个了解。

“许多伟大科学理论的发现都始于猜想，最后加以证实”，在计算机科学中这条理论同样适用。当不知道问题出在哪的时候，要善于从我们所掌握的现象、信息中提炼出关键，然后做出相应的假设与猜想，最后通过一系列手段加以证实。

通过翻阅资料、Google、Baidu 等方式，关于什么情况下可能会引起 Full GC 频繁发生，老年代使用比例持续居高不下等，我收集到了一些有用的信息：

1. 大对象直接进入老年代因此频繁 Full GC；
2. 静态变量过多，变量生命周期过长，存活率过高，造成老年代过大；
3. 内存泄露导致无用对象晋升老年代并无法被 GC 回收。

好了，结合我们目前所掌握的信息，看来第二点和第三点的可能性比较大。

3.5 获取堆转储文件

要论证第二点或者第三点，必然要了解程序运行过程中内存的使用情况。JDK 同样提供了查看内存使用快照、导出内存堆文件等功能，相关命令如下：

• jmap -histo pid：输出 heap 的直方图，包括类名，对象数量，对象占用大小等
• jmap -histo:live pid：同上，主动触发一次 Full GC，即只输出存活对象的信息
• jmap -dump:format=b,file=路径/文件名 pid：生成指定进程的 dump（堆转储）文件
  • 堆转储文件是反映堆使用情况的内存镜像，其中主要包括系统信息、虚拟机属性、完整的线程 dump、所有类和对象的状态等。一般在内存不足，GC 异常等情况下，需要分析内存使用情况，我们就会去打印 dump
• jmap -dump:[live]format=b,file=路径/文件名 pid：也是主动触发一次 Full GC 后随即生成 dump 文件
  • 一般来说，解决内存问题或优化内存，只需统计活着的对象就足够了。如果未传递此选项，则所有对象（即使是准备好进行垃圾回收的对象）都将打印在堆转储文件中。它会增加堆转储文件的大小，同时影响分析结果

以上命令都会造成线上程序的假死，会卡死一段时间，所以线上程序谨慎使用，如果服务是集群的话，可以在运行该命令之前摘掉此机器节点。也可以在业务低峰期偷偷使用~

关于如何获取堆转储文件的方式其实有很多，上述最后两种方式算是实时获取，其他获取方式如下：

• 设置 -XX:+HeapDumpOnOutOfMemoryError、-XX:HeapDumpPath=路径/文件名 JVM 参数：当应用抛出 OutOfMemoryError 时自动生成 dump 文件
• -XX:+HeapDumpBeforeFullGC：在执行一次 FGC 之前生成 dump 文件
• -XX:+HeapDumpAfterFullGC：在执行一次 FGC 之后生成 dump 文件

后两个参数主要用于调试，因此问题解决后需要关掉。关于 Java 进程运行时如何动态开启、关闭或配置 JVM 参数，可以阅读这篇文章：jinfo:JAVA进程运行时修改虚拟机参数利器（无需重启）。

3.6 分析堆转储文件

在线上生成 dump 文件后，我们可以使用 scp 命令等方式将其传输至本地。关于分析 dump 文件的利器有很多，Windows 系统下甚至 JDK 安装包里自带 JVisualVM.exe 可视化 dump 文件分析程序。由于博主使用的是 Mac，无奈只能在官网下载了 JVisualVM 程序。

关于 JVisualVM 的介绍及使用不再赘述，有兴趣的可以自行查阅相关资料。

使用 JVisualVM 读入导出的 dump 文件，查看目前内存中各对象数量、所占大小等信息：

如上图，我已经按对象所占内存的大小进行了排序，问题展现的十分明显，即使在 Full GC 之后 char[] 也就是 String 类型的对象依然占用了整个堆内存的 87.6%，接近 90%，再看这些 String 的内容，都是 log4j2 所打印的日志！

3.7 结论：log4j2引起的内存泄露

还记得刚才关于引起老年代使用比例持续居高不下的三个猜测吗？看来静态变量过多这一猜测也可以排除了，从 dump 文件所展示的信息来看，应该是内存泄露没有错了。

log4j2 会引起内存泄露吗？如果会，是怎么导致内存泄露的呢？继续 Google、Baidu，果然被我查阅到了相关资料：记录一次log4j2导致的内存泄漏。

dump 文件所展示的信息基本与这篇文章讲述的如出一辙，最后再看看自己的应用程序所用的 log4j2 版本以及相关源码，嗯，是这个问题没错了。

遂修改上线，观测监控，查看 GC 是否正常：

可以明显看到老年代所使用的内存大小以及 MIXGC 后的效果相比上线前有了大幅改善，GC 优化至此完美结束~

4 附言

• 在某些情况下（概率较小），Java 堆设置的太小也可能频繁的引起 Full GC，关于如何设置或调整 Java 堆的大小，可以参考这篇文章：JVM参数调优-设置堆、新生代、老年代、持久代大小
  • 注意：上述文章中的内容应该有些许错误，大家辩证看待。如何主动触发一次 Full GC，前面已经讲过很多方式了，不再赘述。引入这篇文章的目的主要在于让大家了解如何设置 Java 堆以及堆中各个区域的大小（G1 收集器只关注 Java 堆的大小即可）
• GC 优化的核心思路在于：尽可能让对象在新生代中分配和回收，尽量避免过多对象进入老年代，导致对老年代频繁进行垃圾回收，同时给系统足够的内存减少新生代垃圾回收次数

5 参考阅读

1. JDK工具（查看JVM参数、内存使用情况及分析等）
2. Java中会出现内存泄露吗？
3. 老大难的GC原理及调优，这下全说清楚了