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

本文涉及的产品
全局流量管理 GTM,标准版 1个月
云解析 DNS,旗舰版 1个月
公共DNS(含HTTPDNS解析),每月1000万次HTTP解析
简介: 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日志看一下。

1187916-20220112111054628-265832633.png


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文件,然后点击分析。(分析的速度根据日志的多少而定,可能会比较慢)

1187916-20220112150654646-1505388261.png

接下来看看分析结果:


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(关键指标)


1187916-20220112154622135-2070091509.png

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

Interactive Graphs

1187916-20220112154734507-229859618.png

  • GC前后堆空间大小


1187916-20220112155224467-942944280.png


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

Memory Leak

1187916-20220112155408092-1979468680.png

GC Causes

1187916-20220112155505342-2036172181.png

GC产生的原因分析

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


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


1187916-20220112155839525-1615483838.png

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

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
23天前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法,重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层,允许开发者使用统一的日志接口,而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback,推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback,以及如何使用Lombok简化日志记录。最后,提供了一些日志配置的最佳实践,包括滚动日志、统一日志格式和提高日志性能的方法。
170 30
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
|
27天前
|
运维 Prometheus 监控
特定用途的日志分析工具
【10月更文挑战第20天】
50 5
|
27天前
|
存储 机器学习/深度学习 传感器
商业日志分析工具
【10月更文挑战第20天】
46 5
|
27天前
|
存储 运维 监控
开源日志分析工具
【10月更文挑战第20天】
55 3
|
27天前
|
存储 监控 Java
JVM进阶调优系列(8)如何手把手,逐行教她看懂GC日志?| IT男的专属浪漫
本文介绍了如何通过JVM参数打印GC日志,并通过示例代码展示了频繁YGC和FGC的场景。文章首先讲解了常见的GC日志参数,如`-XX:+PrintGCDetails`、`-XX:+PrintGCDateStamps`等,然后通过具体的JVM参数和代码示例,模拟了不同内存分配情况下的GC行为。最后,详细解析了GC日志的内容,帮助读者理解GC的执行过程和GC处理机制。
|
2月前
|
Arthas 监控 Java
JVM知识体系学习七:了解JVM常用命令行参数、GC日志详解、调优三大方面(JVM规划和预调优、优化JVM环境、JVM运行出现的各种问题)、Arthas
这篇文章全面介绍了JVM的命令行参数、GC日志分析以及性能调优的各个方面,包括监控工具使用和实际案例分析。
51 3
|
2月前
|
存储 数据可视化 安全
一个简单案例,带你看懂GC日志!
一个简单案例,带你看懂GC日志!
一个简单案例,带你看懂GC日志!
|
2月前
|
Python
log日志学习
【10月更文挑战第9天】 python处理log打印模块log的使用和介绍
35 0
|
2月前
|
数据可视化
Tensorboard可视化学习笔记(一):如何可视化通过网页查看log日志
关于如何使用TensorBoard进行数据可视化的教程,包括TensorBoard的安装、配置环境变量、将数据写入TensorBoard、启动TensorBoard以及如何通过网页查看日志文件。
223 0
|
2月前
|
XML JSON Java
Logback 与 log4j2 性能对比:谁才是日志框架的性能王者?
【10月更文挑战第5天】在Java开发中,日志框架是不可或缺的工具,它们帮助我们记录系统运行时的信息、警告和错误,对于开发人员来说至关重要。在众多日志框架中,Logback和log4j2以其卓越的性能和丰富的功能脱颖而出,成为开发者们的首选。本文将深入探讨Logback与log4j2在性能方面的对比,通过详细的分析和实例,帮助大家理解两者之间的性能差异,以便在实际项目中做出更明智的选择。
255 3