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

简介: 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

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

相关实践学习
通过日志服务实现云资源OSS的安全审计
本实验介绍如何通过日志服务实现云资源OSS的安全审计。
相关文章
|
10月前
|
监控 安全 BI
防火墙事件日志及日志分析
在网络安全防护体系中,防火墙作为抵御外部威胁的第一道防线,其重要性不言而喻。而对防火墙日志进行分析,更是深入了解网络流量、发现潜在安全风险的关键手段。
755 1
|
9月前
|
监控 容灾 算法
阿里云 SLS 多云日志接入最佳实践:链路、成本与高可用性优化
本文探讨了如何高效、经济且可靠地将海外应用与基础设施日志统一采集至阿里云日志服务(SLS),解决全球化业务扩展中的关键挑战。重点介绍了高性能日志采集Agent(iLogtail/LoongCollector)在海外场景的应用,推荐使用LoongCollector以获得更优的稳定性和网络容错能力。同时分析了多种网络接入方案,包括公网直连、全球加速优化、阿里云内网及专线/CEN/VPN接入等,并提供了成本优化策略和多目标发送配置指导,帮助企业构建稳定、低成本、高可用的全球日志系统。
945 54
|
7月前
|
运维 安全 数据可视化
日志审查安排工具实战攻略:中小团队如何通过日志审查安排工具建立可控、安全的审查机制?
在审计敏感时代,日志审查安排工具成为安全运维与合规管理的关键利器。它实现审查任务的流程化、周期化与可视化,支持多系统协作、责任到人,确保“可控、可查、可追”的日志治理。工具如板栗看板、Asana、Monday 等提供任务调度、问题闭环与合规对接能力,助力企业构建高效、透明的日志审查体系,提升安全与合规水平。
|
9月前
|
SQL 监控 关系型数据库
MySQL日志分析:binlog、redolog、undolog三大日志的深度探讨。
数据库管理其实和写小说一样,需要规划,需要修订,也需要有能力回滚。理解这些日志的作用与优化,就像把握写作工具的使用与运用,为我们的数据库保驾护航。
396 23
|
8月前
|
JavaScript API 开发工具
HarmonyOS NEXT实战:日志工具
本文介绍了在HarmonyOS Next应用开发中,如何封装一个简单易用的日志工具LoggerKit。通过使用系统提供的HiLog API,开发者可以灵活输出不同级别的日志信息(DEBUG、INFO、WARN、ERROR、FATAL),用于分析应用运行状态和调试逻辑问题。文章详细说明了日志级别、参数配置及使用注意事项,并提供了完整的TypeScript封装示例代码,便于实际项目集成与应用调试。
201 0
|
11月前
|
监控 Java 应用服务中间件
Tomcat log日志解析
理解和解析Tomcat日志文件对于诊断和解决Web应用中的问题至关重要。通过分析 `catalina.out`、`localhost.log`、`localhost_access_log.*.txt`、`manager.log`和 `host-manager.log`等日志文件,可以快速定位和解决问题,确保Tomcat服务器的稳定运行。掌握这些日志解析技巧,可以显著提高运维和开发效率。
1233 13
|
11月前
|
缓存 Java 编译器
|
11月前
|
监控 Shell Linux
Android调试终极指南:ADB安装+多设备连接+ANR日志抓取全流程解析,覆盖环境变量配置/多设备调试/ANR日志分析全流程,附Win/Mac/Linux三平台解决方案
ADB(Android Debug Bridge)是安卓开发中的重要工具,用于连接电脑与安卓设备,实现文件传输、应用管理、日志抓取等功能。本文介绍了 ADB 的基本概念、安装配置及常用命令。包括:1) 基本命令如 `adb version` 和 `adb devices`;2) 权限操作如 `adb root` 和 `adb shell`;3) APK 操作如安装、卸载应用;4) 文件传输如 `adb push` 和 `adb pull`;5) 日志记录如 `adb logcat`;6) 系统信息获取如屏幕截图和录屏。通过这些功能,用户可高效调试和管理安卓设备。
|
11月前
|
存储 监控 Java
G1原理—7.G1的GC日志分析解读
本文进行了TLAB的GC日志解读、YGC的GC日志解读、模拟YGC(单次GC及多次GC的不同场景)、打开实验选项查看YGC的详情日志信息、Mixed GC日志信息之初始标记过程、Mixed GC日志信息之混合回收过程。