写点什么

【JVM 故障问题排查心得】「GC 内存诊断」一文教你如何打印及分析 JVM 的 GC 日志(实战分析上篇)

作者:洛神灬殇
  • 2023-04-19
    江苏
  • 本文字数:3548 字

    阅读完需:约 12 分钟

【JVM故障问题排查心得】「GC内存诊断」一文教你如何打印及分析JVM的GC日志(实战分析上篇)

当我们在开发 Java 应用程序时,JVM 的 GC(垃圾回收)是一个非常重要的话题。GC 的作用是回收不再使用的内存,以便程序可以继续运行。在 JVM 中,GC 的日志记录了 GC 的详细信息,包括 GC 的类型、时间、内存使用情况等。在本文中,我们将介绍 JVM GC 日志的格式、含义和分析方法。



JVM GC 日志格式

JVM GC 日志的格式通常是一系列以时间戳为基础的事件,每个事件都包含了 GC 的详细信息。以下是一个典型的 JVM GC 日志的示例:


2021-01-01T00:00:00.000+0800: 1.000: [GC (Allocation Failure) 1.000: 1024K->512K(4096K), 0.0010000 secs]
复制代码


其中,时间戳的格式为[ISO 8601],GC 类型为“GC (Allocation Failure)”,GC 发生的时间为 1.000 秒,GC 前后内存使用情况分别为 1024K 和 512K,总内存为 4096K,GC 耗时为 0.001 秒。



JVM GC 日志含义

JVM GC 日志包含了大量的信息,可以帮助我们了解 JVM 的内存使用情况和 GC 的性能。以下是一些常见的 GC 日志含义:


  • GC 类型:GC 的类型,如“GC (Allocation Failure)”表示由于内存分配失败而触发的 GC。

  • 时间戳:GC 发生的时间戳,通常是以秒为单位的浮点数。

  • 内存使用情况:GC 前后内存使用情况,包括已使用内存、总内存等。

  • GC 耗时:GC 的耗时,通常是以秒或毫秒为单位的浮点数。

JVM GC 日志分析方法

JVM GC 日志的分析可以帮助我们了解 JVM 的内存使用情况和 GC 的性能,以便优化应用程序的性能。以下是一些常见的 JVM GC 日志分析方法:


  • 使用 GCViewer 等工具:GCViewer 是一款免费的 GC 日志分析工具,可以帮助我们可视化地分析 JVM GC 日志。使用 GCViewer 可以轻松地查看 GC 的类型、时间、内存使用情况等。

  • 分析 GC 日志文件:我们可以使用文本编辑器等工具来分析 GC 日志文件。通过分析 GC 日志文件,我们可以了解 GC 的类型、时间、内存使用情况等,以便优化应用程序的性能。

  • 调整 GC 参数:通过调整 JVM 的 GC 参数,我们可以优化 GC 的性能,以便提高应用程序的性能。例如,我们可以通过调整-Xmx 和-Xms 参数来调整 JVM 的堆大小,以便优化 GC 的性能。

开启 JVM-GC 日志的启动参数

  1. 如果需要打印 GC 日志,那么首先得把 JVM-GC 日志进行输出到本地文件,一般我们会在 JVM 启动的时候添加参数:

  2. -XX:+PrintGCDetails:打印 GC 日志细节

  3. -XX:+PrintGCTimeStamps:打印 GC 日志时间

  4. -Xloggc:gc_view.log:将 GC 日志输出到指定的磁盘文件上去,这里会把 gc.log 输出到项目根路径

  5. 当 JVM 在运行过程中如果发生 GC,那么将会把 GC 日志输出到 gc_view.log 中。

GC 查看案例

JVM 参数中加入 GC 日志的打印选型,jvm 参数如下所示:


-XX:NewSize=5242880 -XX:MaxNewSize=5242880 -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log
复制代码

JVM 参数解析

配置 JVM 参数

  • -XX:NewSize=5242880 : 初始新生代大小

  • -XX:MaxNewSize=5242880:最大新生代大小

  • -XX:InitialHeapSize=10485760:初始堆大小

  • -XX:MaxHeapSize=10485760:最大堆大小

  • -XX:SurvivorRatio=8:Eden 区就是 Survivor 区的 8 倍,所以 Eden 区占 4M,两个 Survivor 都是占 0.5M。

  • -XX:MaxTenuringThreshold=15:那么新生代对象只有达到 15 岁才会进入老年代。

  • -XX:PretenureSizeThreshold=10485760:指定了大对象阈值是 10MB,那么只有大于 10M 的对象才能直接在老年代分配

  • -XX:+UseParNewGC:使用 ParNew

  • -XX:+UseConcMarkSweepGC:CMS 垃圾回收器




  • -XX:+PrintGCDetails:打印详细的 gc 日志

  • -XX:+PrintGCTimeStamps:这个参数可以打印出来每次 GC 发生的时间

  • -Xloggc:gc.log:这个参数可以设置将 gc 日志写入一个磁盘文件。

对象是如何分配在 Eden 区

我们针对于上述代码的内存进行分析,最开始我们定义和初始化了字节数组:new byte[1024 * 1024],并且对于同一个引用,我们分配了 3 个相同大小的字节数组,每个数组都是 1MB。


public static void main(String[] args) {    byte[] arrayInit = new byte[1024 * 1024];    arrayInit = new byte[1024 * 1024];    arrayInit = null;    //触发Young GC    byte[] arrayInit2 = new byte[2 * 1024 * 1024];}
复制代码
内存区域分析
  1. 定义 array1 这个局部变量依次引用这三个对象,最后还把 array1 这个局部变量指向了 null,那么在 JVM 中是如何运行的呢?


初始化数组对象


byte[] arrayInit = new byte[1024 * 1024];。
复制代码


在 JVM 的 Eden 区内存储一个 1MB 的对象,同时在 main 线程的栈中会压入一个 main 方法的栈帧,在 main 方法的栈帧内部,会有一个“arrayInit ”变量,这个变量是指向堆内存 Eden 区的那个 1MB 的数组。



接着我们看第二行代码


arrayInit = new byte[1024 * 1024];
复制代码


当执行了这行代码之后,便会在堆中的 Eden 区中再次分配一个数组,并且让之前的局部变量指向第二个数组,然后第一个数组就没人引用了,此时第一个数组就成了没人引用的“垃圾对象”了,如下图所示。



接着我们来看第三行代码:array1 = null; 这行代码一执行,就让 arrayInit 这个变量什么都不指向了,此时会导致之前创建的 2 个数组全部变成垃圾对象,如下图。



在项目的根路径下,就可以看到一个 gc.log,点进去查看:


0.383: [GC (Allocation Failure) 0.384: [ParNew: 3543K->512K(4608K), 0.0024598 secs] 3543K->1828K(9728K), 0.0026607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]0.386: [GC (Allocation Failure) 0.387: [ParNew: 2627K->0K(4608K), 0.0015255 secs] 3943K->1828K(9728K), 0.0015985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]Heap par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000) concurrent mark-sweep generation total 5120K, used 1828K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000) Metaspace       used 3101K, capacity 4620K, committed 4864K, reserved 1056768K  class space    used 327K, capacity 392K, committed 512K, reserved 1048576K
复制代码


从上面内容中可以看到进行了两次 GC。


0.383: [GC (Allocation Failure)0.384: [ParNew: 3543K->512K(4608K), 0.0024598 secs] 3543K->1828K(9728K), 0.0026607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
复制代码


从上面的内容可以得出:


  • 在第 0.383 秒,发生 Allocation Failure,就是给对象分配内存的时候内存空间不够了,

  • [ParNew: 3543K->512K(4608K),0.0024598 secs]

  • 新生代的总内存大小为 4608KB(4M 的 Eden 区加上了 0.5M 的 Survivor From 区,一共是 4.5M,即 4608M);

  • Young GC 之前,新生代占用内存大小为 3543KB(三个 1M 的数组,加上 471KB 的“未知内容”);

  • Young GC 之后,剩余了 512KB(“未知内容”)。

  • 在第 0.384 秒的时候,使用 ParNew 垃圾回收器进行了 Young GC。

  • 3543K->1828K(9728K)

  • 整个堆内存大小为 9728KB(即 4M 的 Eden 区加上 0.5M 的 Survivor 区加上 5M 的老年代大小,9.5M,即 9728KB)。

  • 在 Young GC 之前,堆内存共有 3543KB 内存被占用(三个 1M 的数组,加上 471KB 的“未知内容”);

  • 在 Young GC 之后,堆内存共有 1828KB。




0.386: [GC (Allocation Failure) 0.387: [ParNew: 2627K->0K(4608K), 0.0015255 secs] 3943K->1828K(9728K), 0.0015985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
复制代码


之后输出了 Young GC 之后的堆内存使用快照:


Heap par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000) concurrent mark-sweep generation total 5120K, used 1828K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000) Metaspace       used 3101K, capacity 4620K, committed 4864K, reserved 1056768K  class space    used 327K, capacity 392K, committed 512K, reserved 1048576K
复制代码


可以看到新生代占用了 2098KB(一个 2M 的数组,还有一点“未知内容”);Eden 区被占用了 51%,Survivor From 和 Survivor To 使用率为 0%,CMS 管理的老年代被使用了 1828KB。



结论

JVM GC 日志是一个非常重要的话题,可以帮助我们了解 JVM 的内存使用情况和 GC 的性能。通过分析 JVM GC 日志,我们可以优化应用程序的性能,提高应用程序的稳定性和可靠性。

用户头像

洛神灬殇

关注

🏆 InfoQ写作平台-签约作者 🏆 2020-03-25 加入

【个人简介】酷爱计算机科学、醉心编程技术、喜爱健身运动、热衷悬疑推理的“极客达人” 【技术格言】任何足够先进的技术都与魔法无异 【技术范畴】Java领域、Spring生态、MySQL专项、微服务/分布式体系和算法设计等

评论

发布
暂无评论
【JVM故障问题排查心得】「GC内存诊断」一文教你如何打印及分析JVM的GC日志(实战分析上篇)_JVM_洛神灬殇_InfoQ写作社区