20.GC日志详解及日志分析工具

分析JVM性能，肯定要看GC日志，那么GC日志中各个参数都代表什么含义呢？祥看下文。
日志导出来以后，用肉眼看，太费劲了，来看看有什么好用的工具对GC日志进行分析。不管能分析，还有推荐解决方案哦。

一、GC日志

我们在打印日志的时候，增加下面的参数，可以打印更加详细的日志

1. 日志命令解析

‐Xloggc:./gc‐%t.log ‐XX:+PrintGCDetails ‐XX:+PrintGCDateStamps ‐XX:+PrintGCTimeStamps ‐XX:+PrintGCCause ‐XX:+UseGCLogFileRotation ‐XX:NumberOfGCLogFiles=10 ‐XX:GCLogFileSize=100M
  • ‐Xloggc参数：指定gc日志的保存地址。这里指定的是当前目录，文件名以gc-+时间戳.log打印。%t表示时间戳
  • ‐XX:+PrintGCDetails：在日志中打印GC详情。
  • ‐XX:+PrintGCDateStamps：在日志中打印GC的时间
  • ‐XX:+PrintGCTimeStamps：在日志中打印GC耗时
  • ‐XX:+PrintGCCause ： [这个参数没查到]
  • ‐XX:+UseGCLogFileRotation：这个参数表示以滚动文件的形式打印日志
  • ‐XX:NumberOfGCLogFiles：GC日志文件的最大个数，这里设置10个
  • ‐XX:GCLogFileSize：GC日志每个文件的最大容量，这里是100M

2. 日志内容解析

1) 新生代YoungGen内存分配失败触发Minor GC--日志解析

2022-01-11T17:51:35.992-0800: 47.713: [GC (Allocation Failure) [PSYoungGen: 1280509K->89599K(1308160K)] 1396384K->217194K(1509376K), 0.0251936 secs] [Times: user=0.08 sys=0.01, real=0.02 secs]
  • 2022-01-11T17:51:35.992-0800：能够打印这个时间是因为设置了‐XX:+PrintGCDateStamps参数。打印日志输出的时间
  • 47.713：从jvm启动直到垃圾收集发生所经历的时间。这个时间是因为设置了‐XX:+PrintGCTimeStamps参数
  • GC：表示这是一次Minor GC（新生代垃圾收集）；
  • (Allocation Failure)：触发GC的原因是，给Young Gen内存分配失败导致的
  • [PSYoungGen: 1280509K->89599K(1308160K)] 提供了新生代空间的信息，
    • PSYoungGen，表示新生代使用的是多线程垃圾收集器Parallel Scavenge。
    • 1280509K表示垃圾收集之前新生代占用空间，
    • 89599K表示垃圾收集之后新生代的空间。
    • 括号里的1308160K表示整个年轻代的大小。
    • 新生代又细分为一个Eden区和两个Survivor区, Minor GC之后Eden区为空，6577K就是Survivor占用的空间。
  • 1396384K->217194K(1509376K)
    • 1396384K：表示垃圾收集之前Java堆占用的大小
    • 217194K：表示垃圾收集之后Java堆占用的大小
    • 1509376K：总堆大小1509376K，包括新生代和年老代
  • 0.0251936 secs：表示垃圾收集过程所消耗的时间。
  • [Times: user=0.08 sys=0.01, real=0.02 secs]：提供cpu使用及时间消耗
    • user是用户模式垃圾收集消耗的cpu时间，实例中垃圾收集器消耗了0.08秒用户态cpu时间
    • sys是消耗系统态cpu时间
    • real是指垃圾收集器消耗的实际时间
  • 由新生代和Java堆占用大小可以算出年老代占用空间，
    • Java堆空间总大小1509376K，新生代空间总大小1308160K，那么老年代空间总大小是1509376K-1308160K=201216K；
    • 垃圾收集之前老年代占用的空间为1396384K-1280509K=115875K
    • 垃圾收集之后老年代占用空间217194K-89599K=127595k.

2) 元数据（方法区）空间不足触发Full GC--日志解析

2022-01-11T17:54:45.790-0800: 4.307: [Full GC (Metadata GC Threshold) [PSYoungGen: 12761K->0K(497664K)] [ParOldGen: 15911K->18963K(108032K)] 28672K->18963K(605696K), [Metaspace: 34603K->34603K(1081344K)], 0.0401502 secs] [Times: user=0.16 sys=0.00, real=0.04 secs]

fullGC 触发的原因是：元空间（方法区）空间不足

3) 元数据（方法区）空间不足触发MinofGC--日志解析

2022-01-11T17:54:45.782-0800: 4.299: [GC (Metadata GC Threshold) [PSYoungGen: 37195K->12761K(497664K)] 53098K->28672K(577536K), 0.0078608 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

Minor GC触发的原因：元空间不足

4） 系统调用触发GC--日志解析

系统调用触发GC， JVM内部环境认为此时可以进行一次垃圾收集

2022-01-11T17:54:53.979-0800: 12.496: [Full GC (Ergonomics) [PSYoungGen: 49151K->0K(1077760K)] [ParOldGen: 91750K->95410K(221184K)] 140902K->95410K(1298944K), [Metaspace: 53259K->53259K(1097728K)], 0.1806514 secs] [Times: user=0.96 sys=0.01, real=0.19 secs]

二、实战：项目启动时速度很慢

我们来观察一下，当项目启动的时候，启动耗时特别长，这时可以打印GC日志看一下。

image

2022-01-12T11:05:59.658-0800: 1.334: [GC (Allocation Failure) [PSYoungGen: 65536K->4358K(76288K)] 65536K->4374K(251392K), 0.0196609 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

2022-01-12T11:06:00.062-0800: 1.738: [GC (Allocation Failure) [PSYoungGen: 69894K->5059K(141824K)] 69910K->5147K(316928K), 0.0060396 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 

2022-01-12 11:06:00,193 main ERROR Console contains an invalid element or attribute "append"
  
2022-01-12T11:06:00.886-0800: 2.561: [GC (Allocation Failure) [PSYoungGen: 136131K->10741K(141824K)] 136219K->11359K(316928K), 0.0159439 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 

2022-01-12T11:06:00.958-0800: 2.634: [GC (Metadata GC Threshold) [PSYoungGen: 23884K->7144K(272896K)] 24502K->7771K(448000K), 0.0063136 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

2022-01-12T11:06:00.965-0800: 2.640: [Full GC (Metadata GC Threshold) [PSYoungGen: 7144K->0K(272896K)] [ParOldGen: 626K->7038K(88576K)] 7771K->7038K(361472K), [Metaspace: 20521K->20520K(1067008K)], 0.0280148 secs] [Times: user=0.10 sys=0.01, real=0.03 secs]

当项目启动1.3s的时候，便开始触发Minor GC了。因为项目刚刚启动的时候，要加载很多类，随后2.640的时候便触发了一次Full GC，触发的原因是元数据空间不足导致。元数据空间[Metaspace: 20521K->20520K(1067008K)]消耗了20M了，垃圾回收之后，元数据空间基本上没有被回收，因为元数据空间保存的是类信息。我们知道元数据默认空间大小是21M，如果空间不足会触发Full GC，然后扩容。

2022-01-12T11:06:04.538-0800: 6.214: [Full GC (Metadata GC Threshold) [PSYoungGen: 11694K->0K(466944K)] [ParOldGen: 13317K->17995K(115200K)] 25011K->17995K(582144K), [Metaspace: 34079K->34079K(1079296K)], 0.0563024 secs] [Times: user=0.15 sys=0.00, real=0.06 secs]

在项目启动的第6s，再次触发了Full GC，原因也是元数据空间不足导致。这次元数据空间[Metaspace: 34079K->34079K(1079296K)]消耗了34M，垃圾回收完毕以后，也是基本没被回收。但是我们可以看出，元数据空间扩容了，从21M扩到了34M.

所以，如果项目启动的时候要加载的类很多，元数据空间就会不断的扩容，本身这个扩容的过程就是很耗时的。

为了避免这个情况，我们可以在项目启动的时候提前设置好元数据空间的大小，避免其频繁的扩容.

 ‐XX:MetaspaceSize=256M ‐XX:MaxMetaspaceSize=256M

我们重新配置参数，启动项目，看看效果, 发现，Full GC少了。

1  ‐Xloggc:./gc‐adjust‐%t.log -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M ‐XX:+PrintGCDetails -XX:+Print GCDateStamps -XX:+PrintGCTimeStamps ‐XX:+PrintGCCause ‐XX:+UseGCLogFileRotation ‐XX:NumberOfGCLogFiles=10 ‐XX:GCLogFileSize=100M

三、日志分析工具

我们看到日志，尤其是CMS和G1的日志，直接看日志文档都是很不方便的，密密麻麻的文字，其实市面上已经有一些日志分析工具了。今天我们就来给大家介绍一款：gceasy.io

网址：https://gceasy.io/

这款工具不需要我们下载软件，他是在线的。我们要做的就是两步：

步骤一：导出GC日志到本地磁盘

步骤二：将本地日志上传到gceasy.io上，进行分析

下面我们来具体实战一下：

第一步：导出日志

-Xloggc:/Users/lxl/Downloads/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause
  • ‐Xloggc参数：指定gc日志的保存地址。这里指定的是当前目录，文件名以gc-+时间戳.log打印。%t表示时间戳
  • ‐XX:+PrintGCDetails：在日志中打印GC详情。
  • ‐XX:+PrintGCDateStamps：在日志中打印GC的时间
  • ‐XX:+PrintGCTimeStamps：在日志中打印GC耗时
  • ‐XX:+PrintGCCause ： [这个参数没查到]
  • ‐XX:+UseGCLogFileRotation：这个参数表示以滚动文件的形式打印日志
  • ‐XX:NumberOfGCLogFiles：GC日志文件的最大个数，这里设置10个
  • ‐XX:GCLogFileSize：GC日志每个文件的最大容量，这里是100M

我们把日志下载到Downloads文件夹下了。以下便是GC日志的全部内容

Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for bsd-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 20:16:16 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 16777216k(1745536k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=268435456 -XX:+ManagementServer -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2022-01-12T15:02:37.044-0800: 0.839: [GC (Allocation Failure) [PSYoungGen: 65536K->4400K(76288K)] 65536K->4416K(251392K), 0.0043915 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2022-01-12T15:02:37.308-0800: 1.103: [GC (Allocation Failure) [PSYoungGen: 69936K->4959K(76288K)] 69952K->5047K(251392K), 0.0046449 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:37.625-0800: 1.420: [GC (Allocation Failure) [PSYoungGen: 70495K->7467K(76288K)] 70583K->7563K(251392K), 0.0051392 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2022-01-12T15:02:37.831-0800: 1.627: [GC (Allocation Failure) [PSYoungGen: 73003K->9356K(141824K)] 73099K->9460K(316928K), 0.0072596 secs] [Times: user=0.03 sys=0.01, real=0.00 secs] 
2022-01-12T15:02:37.869-0800: 1.664: [GC (Metadata GC Threshold) [PSYoungGen: 22322K->7049K(141824K)] 22426K->7161K(316928K), 0.0057809 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2022-01-12T15:02:37.875-0800: 1.670: [Full GC (Metadata GC Threshold) [PSYoungGen: 7049K->0K(141824K)] [ParOldGen: 112K->6873K(87040K)] 7161K->6873K(228864K), [Metaspace: 20573K->20571K(1067008K)], 0.0237404 secs] [Times: user=0.09 sys=0.01, real=0.02 secs] 
2022-01-12T15:02:38.392-0800: 2.188: [GC (Allocation Failure) [PSYoungGen: 131072K->7194K(236032K)] 137945K->14075K(323072K), 0.0054542 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
2022-01-12T15:02:39.850-0800: 3.646: [GC (Allocation Failure) [PSYoungGen: 235546K->9697K(270336K)] 242427K->20203K(357376K), 0.0092838 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:40.479-0800: 4.274: [GC (Metadata GC Threshold) [PSYoungGen: 179780K->12779K(397312K)] 190286K->25839K(484352K), 0.0117953 secs] [Times: user=0.04 sys=0.01, real=0.02 secs] 
2022-01-12T15:02:40.491-0800: 4.286: [Full GC (Metadata GC Threshold) [PSYoungGen: 12779K->0K(397312K)] [ParOldGen: 13059K->21448K(132096K)] 25839K->21448K(529408K), [Metaspace: 34068K->34068K(1079296K)], 0.0437361 secs] [Times: user=0.16 sys=0.01, real=0.04 secs] 
2022-01-12T15:02:42.177-0800: 5.972: [GC (Allocation Failure) [PSYoungGen: 384512K->13185K(399872K)] 405960K->34641K(531968K), 0.0115070 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:43.010-0800: 6.806: [GC (Allocation Failure) [PSYoungGen: 397697K->16864K(530432K)] 419153K->58461K(662528K), 0.0248406 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
2022-01-12T15:02:44.338-0800: 8.133: [GC (Allocation Failure) [PSYoungGen: 530400K->26083K(539648K)] 571997K->86488K(671744K), 0.0302789 secs] [Times: user=0.06 sys=0.02, real=0.03 secs] 
2022-01-12T15:02:45.800-0800: 9.595: [GC (Allocation Failure) [PSYoungGen: 539619K->32647K(733696K)] 600024K->99769K(865792K), 0.0280332 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
2022-01-12T15:02:47.765-0800: 11.560: [GC (Allocation Failure) [PSYoungGen: 729479K->41445K(738304K)] 796601K->124936K(870400K), 0.0370655 secs] [Times: user=0.04 sys=0.02, real=0.04 secs] 
2022-01-12T15:02:49.620-0800: 13.415: [GC (Allocation Failure) [PSYoungGen: 738277K->26677K(974848K)] 821768K->114930K(1106944K), 0.0270382 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2022-01-12T15:02:52.146-0800: 15.942: [GC (Allocation Failure) [PSYoungGen: 959541K->17569K(985600K)] 1047794K->110447K(1117696K), 0.0274985 secs] [Times: user=0.05 sys=0.01, real=0.03 secs] 
2022-01-12T15:02:54.110-0800: 17.905: [GC (Allocation Failure) [PSYoungGen: 950433K->10240K(1236480K)] 1043311K->109662K(1368576K), 0.0146713 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:54.692-0800: 18.487: [GC (Metadata GC Threshold) [PSYoungGen: 264005K->3360K(1259520K)] 363427K->109573K(1391616K), 0.0086901 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:54.701-0800: 18.496: [Full GC (Metadata GC Threshold) [PSYoungGen: 3360K->0K(1259520K)] [ParOldGen: 106213K->54092K(208384K)] 109573K->54092K(1467904K), [Metaspace: 56204K->56204K(1101824K)], 0.1487173 secs] [Times: user=0.69 sys=0.01, real=0.14 secs] 
2022-01-12T15:02:57.787-0800: 21.583: [GC (Allocation Failure) [PSYoungGen: 1209856K->49146K(1321984K)] 1263948K->116260K(1530368K), 0.0339265 secs] [Times: user=0.05 sys=0.01, real=0.04 secs] 
2022-01-12T15:03:16.198-0800: 39.994: [GC (Allocation Failure) [PSYoungGen: 1321978K->29589K(1335296K)] 1389092K->101049K(1543680K), 0.0214759 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
2022-01-12T15:03:19.021-0800: 42.816: [GC (GCLocker Initiated GC) [PSYoungGen: 1302421K->60915K(1280512K)] 1373881K->180735K(1488896K), 0.0482886 secs] [Times: user=0.08 sys=0.01, real=0.05 secs] 
2022-01-12T15:03:21.847-0800: 45.642: [GC (Allocation Failure) [PSYoungGen: 1280499K->89087K(1308672K)] 1400321K->228379K(1517056K), 0.0336500 secs] [Times: user=0.10 sys=0.01, real=0.04 secs] 
2022-01-12T15:03:24.516-0800: 48.311: [GC (Allocation Failure) [PSYoungGen: 1308671K->67295K(1257472K)] 1447963K->225652K(1465856K), 0.0381420 secs] [Times: user=0.07 sys=0.02, real=0.04 secs]

第二步：导入分析工具，尽心分析

打开gceasy.io网站，并选择本地的gc文件，然后点击分析。（分析的速度根据日志的多少而定，可能会比较慢）

image

接下来看看分析结果：

JVM memory size (JVM内存大小)

![image-20220112151703421](/Users/luoxiaoli/Library/Application Support/typora-user-images/image-20220112151703421.png)

这里的Allocated和Peak分别表示可分配空间和峰值

  • Allocated：可分配空间大小。具体含义如下：指示为每一代分配的大小。此数据点是从GC日志收集的，因此它可能与JVM系统属性指定的大小相匹配，也可能不匹配。假设您已将总堆大小配置为2gb，而在运行时，如果JVM只分配了1gb，那么在本报告中，您将看到分配的大小仅为1gb

  • Peak： 分配的峰值。具体含义如下：每一代的峰值内存利用率。通常它不会超过分配的大小。然而，在少数情况下，我们也看到峰值利用率超出了分配的大小，特别是在G1 GC中

这里统计的是JVM内存空间的大小

  • 新生代：可分配空间是1.28g，峰值使用是1.28G
  • 老年代：可分配空间201M，峰值是150.63M
  • 元数据：可分配空间1.05G，峰值54M
  • 总计：5.05G，1.44G

Key Performance Indicatiors（关键指标）

image

  • Throughput：吞吐量。指的是处理实际事务花费的时间与GC花费的时间的百分比。这个值越高越好
  • Latency：延迟情况。这里的延迟情况是指的GC过程花费的时间。具体含义如上图

Interactive Graphs

image

  • GC前后堆空间大小

GC统计

image

这里列出了Minor GC 的情况， Full GC的情况， GC停顿统计， 以及总的GC统计

Memory Leak

image

GC Causes

image

GC产生的原因分析

  • 内存分配失败触发GC的情况统计：
  • 元数据空间不足触发GC的情况统计：
  • GCLocker启动的GC触发GC的情况统计 ：

重磅功能---GC分析后的优化

image

只可惜是收费的。据说找问题的准确率还是挺高的。

posted @ 2022-01-12 16:02  盛开的太阳  阅读(3718)  评论(2)  编辑  收藏  举报