这个场景下使用 Skywalking 调用链，发现 JVM 老年代内存没办法回收了！（下篇）...

最新推荐文章于 2024-05-05 01:14:42 发布

Java爱好者社区

最新推荐文章于 2024-05-05 01:14:42 发布

阅读量3.9k

点赞数 6

本文链接：https://blog.csdn.net/david_lua/article/details/102735552

版权

预计阅读时间：12 分钟

本文分为上、下两篇围绕以下几点展开：

01 Skywalking 调用链简介（上篇）
02 接入 Skywalking Agent 后的服务表现（上篇）
03 应用哪些「手段」排查 Jvm 问题的（上篇）
04 结合 Jvm GC 日志分析到底发生了什么（下篇）
05 应用哪些「手段」排查 Jvm 内存泄漏的（下篇）
06 Skywalking 官网中是如何修复的（下篇）

接下来，接续上一篇内容继续展开。

结合 Jvm GC 日志分析到底发生了什么

带你分析下 GC 日志

GC 日志其实很关键的，有助于线上问题排查，查看垃圾回收的过程细节。有人说对线上性能有损耗，其实对于大多数项目这点损耗不算什么，可以忽略，建议都开启。

开启 Jvm GC 日志参数：

-XX:+PrintGCDetails # 打开 GC 日志-XX:+PrintGCDateStamps # 打印 GC 系统时间-XX:+PrintHeapAtGC # GC 前后打印堆内存占用信息

-XX:+PrintGCApplicationStoppedTime # 打印 Jvm 暂停时间-Xloggc:/path/gc.log # 指定 GC 日志路径-XX:+UseGCLogFileRotation # 开启 GC 日志的滚动输出，默认关闭-XX:NumberOfGCLogFiles=5 # 生成 GC 日志文件个数-XX:GCLogFileSize=20M # 每个 GC 日志文件大小

在系统 Jvm 堆中内存调整之前，我们看下当时线上系统，关键 GC 日志：

640?wx_fmt=png

从 Heap before GC 中看到 GC 之前情况：

eden space 已经达到了 100%，说明新生代 Eden 区已经满了。

from space （Survior区）已经达到了 51%，GC 发生时 Jvm 会判断 Survivor 区内，所有存活对象年龄累加的内存占比超过 50%，则会将最大的年龄对象直接晋升到老年代。

正常情况下，每当发生一次 Yong GC 时，GC 日志中会出现 GC（Allocation Failure），此时，新生代会暂定应用（Stop The World），GC 线程执行垃圾回收，通常时间很短，一般是几十毫秒。

GC日志：ParNew（promotion failed）

ParNew 说明了新生代使用的 ParNew GC 回收算法。

promotion failed（担保失败），遇到这个「关键字」要注意，说明新生代内存不足，但对象晋升到老年代也失败了，说明老年代空间不足，无法容纳新晋对象了。

GC日志：

ParNew（promotion failed）8541211K->8354946K(9175040K), 13.5186159 secs

发现新生代垃圾回收时间耗时了 13 秒，虽然没有 Full GC 字样，但实际执行的就是 Full GC，退化为了单线程回收模式，暂停应用，执行垃圾回收完成，你的应用虽然没死掉，但此时会访问巨慢，一直卡顿着。

GC日志：

[CMS: 1721256K->1883732K(2097152K), 5.9388252 secs]

9835967K->1883732K(11272192K)

发生了 Full GC 同时，也会发生 CMS GC 老年代内存回收，垃圾回收耗时 5 秒。

9835967K->1883732K(11272192K) 这段说明了总堆内存，回收后还剩余 1.8g 左右，其实也看到了这 1.8g 就是 CMS 老年代垃圾回收剩余的。

细心的读者，能看到 CMS: 1721256K->1883732K(2097152K)，执行完 CMS 垃圾回收后，内存不降反升了。

因为刚提到了 Survivor 区内存超过 50% 的一部分对象会直接晋升到老年代。上篇文章提到，根据平时业务观察看，老年代内存很少能到 1g，这里已经占用到 1.8g，所以可能发生了内存泄漏了。

当时发现这台服务响应慢时，我们及时从线上摘掉这个服务，避免影响线上其他服务，保留现场分析问题。因使用了 Eureka 注册中心，对 Eureka 界面做了改造，可以支持快速对服务下线、上线、调整权重（自行实现权重算法）操作。

还没完。

当时这台机器并没有立马恢复，上篇文章 jstat 截图看到是一直在发生 FGC。

继续看下面这段关键 GC 日志：

640?wx_fmt=png

发生了 concurrent mode failure ，这个说明老年代内存不足，发生了 CMS GC 之后仍然不足以容纳晋升的对象。

GC日志：

(concurrent mode failure): 1875268K->1877132K(2097152K), 8.4402063 secs

大家看到会说，老年代内 2g，这里目测还剩余200M空间，难道不够了？

通过 CMS （Concurrent Mark Sweep）这个名字，也能知道其使用的标记-清除算法，这种算法的缺陷：并发垃圾回收后，会产生内存碎片，即内存空间不是连续的。

当新生代内存空间满了，发生 Yong GC，Jvm 会执行动态监测机制的判断条件：

1）老年代剩余连续内存空间是否大于新生代内存所有对象大小。

2）若条件1）不符合，则判断，老年代剩余连续内存空间是否大于历次晋升到老年代的对象大小。

如果上述条件都不满足，则会发生一次 GMS GC，要求腾出空间。根据上述 GC 日志看，虽然发生了 CMS GC，但是剩余连续内存空间仍然不足，最终发生了 concurrent mode failure。

频繁发生 CMS GC，会造成两个阶段应用（STW）暂停。

再来一段 CMS GC 完整过程 GC 日志：

640?wx_fmt=png

CMS GC 主要分为了七个阶段：

CMS-initial-mark # 初始标记，发生STW
CMS-concurrent-mark # 并发标记
CMS-concurrent-preclean # 并发预清理
CMS-concurrent-abortable-preclean # 并发中断预清理
CMS Final Mark # 最终标记，发生 STW
CMS-concurrent-mark-sweep # 并发标记清除
CMS-concurrent-reset # 并发重置，为下次GC做准备

频繁发生 CMS GC，会导致垃圾回收线程执行过程抢占系统 CPU 资源，所以也印证了上篇文章提到的，运维反馈该服务器上的 CPU、Load 会比其他机器高的原因。

GC 日志分析工具推荐

1、CMS GC 日志分析

对于 CMS GC 日志分析可参考博文：

https://blogs.oracle.com/poonam/understanding-cms-gc-logs

2、GC Viewer 工具

如果分析 GC 日志，你觉得看起来不是很直观。

也可以使用 GCViewer 这款工具，有图表有 GC 相关的内存数据统计。

640?wx_fmt=png

上图看到发生 FullGC时的异常曲线。

640?wx_fmt=png

Gc pauses、 Full gc pauses、Concurrent GCs，很方便的看到各阶段，Gc 内存情况的占比，便于分析。

3、在线 GC 日志分析工具

下载下来 GC 日志，如果过大建议打个包直接上传，就可以在线分析了，非常方便。

gceasy 地址：https://gceasy.io

Jvm 如何监控

关于 Jvm GC 监控。

在使用 Skywalking 调用链时，也能自动监控 Java 应用的 Jvm 内存、GC指标。

我们线上系统，使用了 OpenFalcon ，结合 jmxon 插件实现监控，需要你的 Java 应用开启 Jmx 端口。

Jvm 上 Jmx 端口开启：

-Dcom.sun.management.jmxremote -Djava.rmi.server.hostname={$SERVER-IP} -Dcom.sun.management.jmxremote.port={$JMX-PORT} -Dcom.sun.management.jmxremote.rmi.port={$JMX-PORT} -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false

服务器上下载 jmxon，修改 conf.properties 配置文件（Jmx 端口和 falcon 上报地址）

在 OpenFalcon 上可以设置告警，发送短信、邮件通知。

核心监控项：

640?wx_fmt=png

监控后的效果：

640?wx_fmt=png

上述截图，模拟演示其中一台机器内存泄漏问题。

我们看到，老年代内存使用量、使用率持续增长，GC 吞吐随之下降。

应用哪些「手段」排查 Jvm 内存泄漏的

内存泄漏问题初步定位

分析完了 GC 日志，接下来我们看下，如何排查 Jvm 内存泄漏问题的。

当时线上系统发生问题后，打印了堆栈内存信息。

jstack 命令：

jstack -l $pid > jstack.log

结合上篇文章提到的阿里开源的 Arthas 在线诊断工具也可以看到，堆栈中线程状态并没有发现什么异常。

根据上面一系列推测，可以通过如下命令查看下可能哪些类占用内存过高。

jmap 命令：

jmap -histo $pid | head -n 20

打印出当前 Jvm 堆栈中类对象实例数量和内存占用。

640?wx_fmt=png

num: 对象编号

#instances：对象实例数量

#bytes：占用的内存字节数

class name：类的名称

上述截图中看到了

org.apache.skywalking.apm.agent.core.dictionary.EndpointNameDictionary$OperationNameKey

这个类对象占用内存，看起来是有些异常，不断的观察发现，该类的 #instances 会不断的增长。

只能说初步判断是这个类引起的，要想进一步确诊，还需要 dump 出堆内对象，转存到文件中。

jmap 命令：

jmap -dump:live,format=b,file=heap.bin <pid>

因该系统 Jvm 内存堆设置较大有 12g，所以当时 dump 出来的内存文件有 8g 左右，可以打包压缩一下，导出到本地。

分析 dump 堆转存文件工具

1）服务器自带命令 jhat

我在服务器上执行 jhat 时，因这个文件特别的大，所以等待时间很长很长，一直没有反应，所以放弃了。

jhat 命令：

jhat -J-Xmx10000m -port <heap dump file>	
执行后启动一个端口默认是7000，启动后可以通过 IP:7000 访问

2）在线分析堆转存文件

在线分析堆转存，你的 dump 文件不能太大，现在在 2g 左右。如果 dump 文件过大，会引导你注册完，还需要付费的。

在线分析堆转存工具：https://fastthread.io/

3）MAT 专业直观的内存分析工具

这里咱们使用 MAT 内存泄漏专业的分析工具。

MAT 工具获取方式：

1）Eclipse 开发工具，直接安装下 MAT 插件。

2）单独下载载 MAT 工具，下载地址：http://www.eclipse.org/mat/downloads.php

因为 dump 出来的文件较大，你需要将 Eclipse 的堆内存设置大一些，这里设置为10g，否则会因为内存不足，没有分析出结果，就自动退出了。

导入 dump 文件，我们来看下 MAT 分析结果：

640?wx_fmt=png

跟 jmap -histo 命令中看到的结果是吻合的，这个 EndpointNameDictionary 类内存占用了 1.3g，已占用到老年代内存的 65%，而且还会持续增长。

查看 Problem Suspect1

看到该类的内存实例对象占比情况：

640?wx_fmt=png

查看 Dominator tree

看到了 EndpointNameDictionary 类的包含了大量的 ConcurrentHashMap 对象。

ConcurrentHashMap 对象展开后，看到了存储的类似于 api/checkTicket/xxxx 的URI地址。

640?wx_fmt=png

根据上述这个结果，结合程序源码就能清楚知晓原因了。

因为我们代码中有通过 Spring RestTemplate 方式去调用第三方接口。

该接口主要用于用户Token鉴权的，接口形式：

api/checkTicket/{userToken}

这里的 {userToken} 每个用户都是不一样的，而 Skywalking Agent 包的这个 EndpointNameDictionary 是存储 Endpoint（Http URI）地址的。

查看 EndpointNameDictionary 类源码:

640?wx_fmt=png

如果Http URI中是动态的绑定参数，就会导致每次都会当做一个新的 Endpoint，进而导致内存不断增长。

EndpointNameDictionary 这个类是使用枚举单例模式，GC Roots 会一直引用 endpointDictionnary 私有成员变量，进入老年代后，即使发生了 CMS GC，也不会回收这个对象。

但是该问题在 Spring MVC 框架中是没有问题的，Agent 插件中已经对这种情况做了优化，Skywalking Agent 的当时版本没有考虑到 RestTemplate 这个模板的问题。

如果使用了Spring Cloud 框架，可以使用 Feign。我们系统代码也比较早了，没有使用 Feign 去调用。

经过以上的分析，得到的结论，我们就知晓了 Jvm 内存泄漏的原因所在了。

Skywalking 官网中是如何修复的

给 Skywalking 社区提个 Issue

Skywalking 项目在快速迭代中，当然核心源码及架构机制，是不会有太大变化的。

基于项目中的这个问题，给 Skywalking github 社区提了一个 Issue。

作者吴晟回复很快，很赞！

Jvm 内存泄漏问题 Issue 参见：

https://github.com/apache/skywalking/issues/3293

解决方案：

在 Agent 客户端中，通过匹配通配符的 URI，按正则方式替换为对应组名。

这样，在 Skywalking Agent 中的 EndpointNameDictionary 字典缓存中存储的就是替换后的组名URI，而不是具体的URI。

Group APIs for the operation name in agent:

https://github.com/apache/skywalking/issues/3298

640?wx_fmt=png

部分功能在 Skywalking core 核心包中实现的，

Skywalking 最大特点就是所有框架，基本都通过插件方式，易于扩展，底层通过字节码插装实现拦截操作。

Spring RestTemplate 同步和异步插件，拦截器中拦截，然后读取 agent.config 中的配置，正则匹配替换URI。

Support op group name in agent config core

https://github.com/apache/skywalking/pull/3299

配合完成 Issue 测试工作

Skywalking Agent 客户端 agent.config 配置文件增加：

plugin.opgroup.resttemplate.rule[/api/checkTicket/{token}]=/api/checkTicket/*

当时配合测试，是自行下载官网开发分支代码，编译打包的 agent。

增加该配置后，Jvm 内存观察一切都正常了，最终解决了内存泄漏问题。

Skywalking 控制台上看到的效果：

640?wx_fmt=png

这个问题已在 Skywalking 6.4.0 稳定分支版本修复了。

该版本于 2019年9月11日已正式发布：

640?wx_fmt=png

本文稍长，希望大家有耐心读完 : )

文章中期望尽量能够重现问题场景，以及排查该问题的过程。

当然，如果大家有疑问或者需要探讨，欢迎下方「留言」，也可以公众号后台联系我。

最后的总结：

1、工欲善其事，必先利其器

排查线上问题，熟练使用各种工具也是很重要的，事半功倍。

2、整体把握，着眼细节

整体掌握对 Jvm 内存结构，垃圾回收算法及原理。

配合 GC 日志及辅助工具深入细节分析。

3、推动开源社区发展

比如提 Issue，如果有能力还可以参与到开源社区建设中，贡献一点力量。

对，就是那个「Github-全球最大的同性交友网站」。

END

点开，扫码即刻关注

您感觉有价值，点击下『在看』吧

Java爱好者社区

关注

6
点赞
踩
14

收藏

觉得还不错? 一键收藏
3
评论
这个场景下使用 Skywalking 调用链，发现 JVM 老年代内存没办法回收了！（下篇）...

本文分为上、下两篇围绕以下几点展开： 01 Skywalking 调用链简介（上篇） 02 接入 Skywalking Agent 后的服务表现（上篇） 03 应用哪些「手段」排查 Jvm问题的（上篇） 04结合 Jvm GC日志分析到底发生了什么（下篇） 05应用哪些「手段」排查 Jvm 内存泄漏的（下篇） 06 Sky...
复制链接

扫一扫