专栏首页IT技术小咖[三步法] 可视化分析定位线上 JVM 问题

[三步法] 可视化分析定位线上 JVM 问题

1. 取 GC 日志文件

gc.log 文件大概张什么样呢,如下图所示:

前提是线上 JVM 配置了以下参数: [题外话:JDK 版本 1.6,现在大部分互联网企业应用系统应该是 1.8 以上了吧 ]

# 在控制台输出GC情况
-verbose:gc 
# GC日志输出
-XX:+PrintGC
# GC日志详细输出
-XX:+PrintGCDetails
# GC输出时间戳
-XX:+PrintGCDateStamps
# GC日志输出指定文件中
-Xloggc:/log/gc.log

2. GC 日志可视化

首先获取到线上 GC 的日志文件后,通过在线日志分析工具(GCeasy)上传文件分析,网址:https://gceasy.io/

如果出现以下页面,说明 GC 日志在线分析已经完成,可视化效果如下所示:

从上图可以发现,“3 problems detected”,即识别出 3 个内存问题。

3. 在线 GC 可视化视图解读

1)JVM memory size(JVM 内存大小)

上图左侧是表格展示,右侧是柱状图?展示,含义是一样的。

按分代策略划分

分配大小

已用大小

年轻代

149.75 M

149.75 M

老年代

5.84 G

5.84 G

永久代

427.52 M

256.5 M

年轻代 + 老年代 + 永久代

6.4 G

6.23 G

[题外话:年轻代是不是分配的太小?]

2) key Performance Indicators(关键指标展示)

从上图可以看出:

  • Throughput:87.041%,即表示该系统吞吐量为 87.041%。一般 95% 以上算优。
  • Latency,即表示系统 GC 的停顿时间,平均暂停时间 70.3 ms,最大暂停时间约 13 s。

将上图的 GC Pause 时间间隔调整为 100 ms,查看结果如下:

上图显示 100 ms 以内的 GC 次数 5105,占总 GC 的 99.53%,说明 GC 的效果还可以。

[题外话:99.53% GC 时间这么短,为何系统宕机了,是死在了余下的 0.47% 的 GC 上!!!]

3)Interactive Graphs(GC 前后堆区大小变化视图)

为了更好的了解 GC 垃圾回收对应的区域,可以参考这篇文章【从 Java 代码如何运行聊到 JVM 和对象的创建-分配-定位-布局-垃圾回收】回顾一下有关 JVM 内存布局的划分情况。

[题外话:对照图例看折线图变化 ]

从上面的折线图可以看出,曲线存在尖锐的变化,可能是问题的所在之处(存在内存泄漏或是内存溢出)。

  • Heap after GC:GC 之后的堆区空间占用大小(堆区包括 Young GC 和 Full GC)

因为 Young Gen 区域的大小只有 149.75 M,所以 Young GC 后还是有对象不停的晋升到 Old Gen,直到老年代分配不了了才发生第一次 CMS GC。

[题外话:细心的你会发现在 10 点 25 分左右就已经发生了一次 Full GC,此时的堆空间仅仅占用了 500M 左右,应该不会发生 Full GC 才对,那么为什么呢?这是由于如果一开始永久代大小没有设置、或者初始值设置的很小,很有可能一开始就执行 CMS。]

  • Heap before GC:GC 之前的堆区空间占用大小(堆区包括 Young GC 和 Full GC)

从 Full GC 之前和之后的图形对比分析,可以看出 JVM 进行 Full GC 时,内存几乎没有被回收(此时年轻代的垃圾回收可以忽略),而对象始终占用堆区大小 6G 左右,所以出现频繁的 Full GC。

  • GC Duration:GC 期间
  • Pause GC Duration:GC 停顿时间

Young GC 耗时的点位于图的最下方(蓝色的方块点),Full GC(红色的三角点)耗时在 11 点之后越来越长,基本都超过了 10s,且特别频繁发生,说明此时 GC 已经无力回天了。

  • Reclaimed Bytes:GC 回收内存大小

从上图可以看出,Young GC 正常(蓝色方块点),每次能回收 120M ~ 140M 的内存,几乎所有的年轻代垃圾都被回收了;而在 11点之后系统频繁发生 Full GC(红色的三角点),但是回收的垃圾几乎为零?回收的垃圾几乎为零?回收的垃圾几乎为零?

  • Young Gen:年轻代 GC 变化

从上图可以看出,Young GC 之前(红线),年轻代内存占用大概有 140M左右,Young GC 之后(紫线),年轻代内存占用大小 20M 以内。年轻代垃圾回收正常。也可以分开显示 Young GC 前后变化,如下图所示:

  • Old Gen:老年代 GC 变化

如上图所示,Old GC 前后的曲线分不清,通过如下操作,可以只显示 Old GC 前的曲线变化或者 Old GC 后的曲线变化:

从上图可以看出,Old GC(老年代垃圾回收)和 Heap 区的 GC 类似,老年代对象占用大小一直在增加,直到10点55分出现拐点,可能存在内存泄漏或溢出,需要结合 Heap Dump 文件分析。

[题外话:一般出现这种尖锐的拐点都是有问题的。]

  • Perm Gen:永久代 GC 变化

永久代一直变化不大,动态分配,占用内存空间小于 450 M。

  • A & P:对象分配与晋升(从年轻代晋升到老年代)

隐藏内存分配的曲线变化,只显示 Young ——> Old 的变化曲线,如下图所示:

4)CMS Collection Phases Statistics(CMS 垃圾收集器统计图表)

从上图最左侧的柱状图,可以清晰看到 CMS GC 的各个阶段(可参考这篇文章【记一次生产频繁出现 Full GC 的 GC日志图文详解】详细了解 CMS 各个阶段都干了啥 )的平均耗时;Full GC 平均耗时长达 11s;上图最右侧的饼状图,展示了各阶段 GC 的累积时间;上图最下面的表格汇总了各个阶段 GC 的次数、时间等相关信息,其中 2 分 40 秒进行了 5081 次 Young GC,平均耗时 31.6 毫秒,3 分 18 秒进行了 18次 Full GC,平均耗时 11 秒。

5)CMS GC Time(CMS GC 时间)

CMS GC 暂停的时间最大约 13s(时间过长),并发 GC 时间最大 5s(影响不大)。

6)Object Stats(对象统计)

从图中可以看出,这段 GC 期间共创建 661.35 G 大小的数据,从年轻代晋升到老年代的共有 11.88 G,平均每秒创建 243.23 M(远远超过分配给年轻代的大小【Young Gen = 149.75M】),平均每秒晋升到老年代的对象有 4.37 M。也就是说对于堆区年轻代分配的空间不太合理。

7)Memory Leak(内存泄漏)

无内存泄漏

8)Safe Point Duration(安全点期间)

日志没有记录。 JVM 需要配置一下参数才会记录 safe point 相关信息:

-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1

[题外话:GC 的标记阶段需要 stop the world(STW),让所有 Java 线程挂起,这样 JVM 才可以安全地来标记对象。safe point 可以用来实现让所有 Java 线程挂起的需求。]

9)GC Causes (GC 原因)

从上图可以看到,在 CMS 收集器触发时,出现了 promotion failed(1次)和 concurrent mode failure(14次)现象(可参考这篇文章【记一次生产频繁出现 Full GC 的 GC日志图文详解】):

  • promotion failed: 该现象是在进行触发年轻代 ParNew GC 时,存活的对象在 Survivor 区放不下,对象只能进入老年代,而此时老年代也放不下导致的。
  • concurrent mode failure: 该现象是在执行 CMS 收集器回收垃圾的过程中同时有存活的对象放入老年代,而此时老年代空间不足,或者在做 ParNew GC 的时候,年轻代 Survivor 区放不下,需要放入老年代,而老年代也放不下而导致的。

4. 从 GC 日志可视化入手,再去 pinpoint 系统监控探究问题所在

1)通过 Pinpoint 监控系统查看频繁发生 Full GC 的系统应用所在的服务器 JVM 参数配置情况,结果如下图所示:

从图中可以了解关于堆区只设置了 3 个参数,几乎其他设置项是默认设置,没有任何优化。

2)Pinpoint 监控堆区的使用,非堆区的内存使用情况:

可以看出,系统从 11点左右开始频繁发生 Major GC(Full GC)。说明这期间系统已经不能对外响应了。CPU 使用率波动不大。 从下图可以看出,系统在 11点左右停止响应了。

也可以通过 Pinpoint 监控获取这段时间的系统请求量,下图中点的密集程度反映各时间请求量的大小,没有激增,分布很均匀,只是存在大量响应耗时较长的请求(慢请求),可能正是因为这些慢请求导致整个系统响应变慢,系统中的大量对象无法被回收。

[题外话:如何知道哪些请求是慢请求呢?在 Pinpoint 中只需要框选上图中最上方的蓝色点即可,找到对应的请求,然后分析原因,解决耗时长的接口。比如数据库长时间不返回结果集导致连接被一直占用,请求第三方接口时未设置超时时间等待响应或是 IO操作未在 finally 中关闭流等,则这些不会自动被 GC 回收的,导致内存泄漏。本文在这不做过多的说明。有机会再详细聊聊这块 ~ ]

5. 接着看 Dump 文件分析

通过 MAT 分析 dump 文件(可参考这篇文章【MAT的使用】),导入 dump 文件即可,等 MAT 解析完会出现如下图所示的界面:

MAT 发现结果会展示一个疑似引起问题的大对象(占堆区的 96.52%),如下图所示:

打开对应的 Domaintor Tree,如下图所示:

按对象的大小排序,依次展开第一个最大的对象中所引用的对象,发现里面有一个集合,该集合里存有 1836555 个对象,导致 OOM 内存溢出,如下图所示:

查看代码,看看是否是 SQL 查询条件缺失,导致返回了表中的所有数据。 [题外话:建议后端服务做参数校验或限制数据库最大返回条数。]

6. 对 JVM 参数的优化及说明

1)可增大年轻代或者 Survivor 区的存储空间,减少 Young GC 的次数。

# 初始堆大小
-Xms6144M
# 最大堆大小
-Xmx6144M
# 初始永久代大小
-XX:PermSize=1024M
# 最大永久代大小
-XX:MaxPermSize=1024M
# 年轻代大小
-Xmn2048M
# Survivor 区占比
-XX:SurvivorRatio=3

2)提前触发 CMS GC 和多次 Full GC 后进行内存整理,以提升 CMS GC 垃圾回收的效率。

# CMS 垃圾回收内存碎片化严重
-XX:+UseCMSCompactAtFullCollection
# 每 5 次 Full GC 之后进行一次老年代空间内存整理
# 而不是每 5 次 CMS 并发 GC 就做一次压缩
-XX:CMSFullGCsBeforeCompaction=5
# 只是用设定的老年代回收阈值(下面指定的75%),和下面的参数配合使用
# 如果不指定,JVM 仅在第一次使用设定值,后续则自动调整。
-XX:+UseCMSInitiatingOccupancyOnly
# 当老年代空间被占 75% 时,就进行 CMS GC
#(而默认占用 92% 时触发 CMS GC)
# 在进行 CMS GC 时应该留更多的空间,
# 防止年轻代晋升老年代失败,出现 concurrent mode failure
-XX:CMSInitiatingOccupancyFraction=75

7. 小结

通过三步法定位线上环境 JVM 问题,如频繁 Full GC 、内存泄漏或发生 OOM 现象,即将 GC 日志、Dump 文件及 APM 监控系统结合在一起观察分析,寻找出问题产生的根本原因,然后才能对症下药,真正解决系统存在的问题或是隐患,使系统性能更稳健,响应更快,从而使用户体验更佳。

本文分享自微信公众号 - IT技术小咖(IT-arch),作者:giserway

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2020-03-21

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 记一次生产频繁出现 Full GC 的 GC日志图文详解

    相信大家都了解 jps、jmap、jstack 等常用 java 堆栈输出命令,有过 dump、gc 分析的经验,面试中会经常被问到有关 JVM 问题,比如你是...

    IT技术小咖
  • JVM故障分析及性能优化实战(VII)——使用MAT的Histogram和Dominator Tree定位溢出源

    上一篇文章概括的介绍了JVM Heap Dump文件生成的方式以及内存分析工具MAT的概要功能,今天讲解如何使用MAT的Histogram和Dominator ...

    IT技术小咖
  • 从 Java 代码如何运行聊到 JVM 和对象的创建-分配-定位-布局-垃圾回收

    概括一下:程序员小张编写好的 Java 源代码文件经过 Java 编译器编译成字节码文件后,通过类加载器加载到内存中,才能被实例化,然后到 Java 虚拟机中解...

    IT技术小咖
  • 从ASP.NET Core 3.0 preview 特性,了解CLR的Garbage Collection

    在阅读这篇文章:Announcing Net Core 3 Preview3的时候,我看到了这样一个特性:

    ShenduCC
  • 成为JavaGC专家(1)—深入浅出Java垃圾回收机制

    对于Java开发人员来说,了解垃圾回收机制(GC)有哪些好处呢?首先可以满足作为一名软件工程师的求知欲,其次,深入了解GC如何工作可以帮你写出更好的Java应用...

    哲洛不闹
  • 老公:怎么排查堆内存溢出啊?

    上次给老公们说过了死循环cpu飙高的排查过程,今天就带着老公们看看堆内存溢出我们一般怎么排查的。

    敖丙
  • 程序员如何优化 Java GC

    本文由CrowHawk翻译,地址:如何优化Java GC「译」,是Java GC调优的经典佳作。

    黄泽杰
  • 如何优化Java GC

    在第一篇 理解 Java GC 中我们学习了不同GC算法的处理过程,GC是如何工作的,什么是年轻代和老年代,JDK7中的5种GC类型,以及每种GC类型对性能的影...

    码代码的陈同学
  • Full GC 和 Minor GC,傻傻分不清楚

    大家可能见到过很多的 GC 名词,比如:Minor GC、Young GC、Full GC、Old GC、Major GC、Mixed GC。

    武培轩
  • 垃圾回收器学习之Full GC和CMS GC的区别

    针对HotSpot VM的实现,它里面的GC其实准确分类只有两大种:Partial GC:并不收集整个GC堆的模式 Young GC:只收集young gen...

    小程故事多

扫码关注云+社区

领取腾讯云代金券