分析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日志看一下。
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
这款工具不需要我们下载软件,他是在线的。我们要做的就是两步:
步骤一:导出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文件,然后点击分析。(分析的速度根据日志的多少而定,可能会比较慢)
接下来看看分析结果:
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(关键指标)
- Throughput:吞吐量。指的是处理实际事务花费的时间与GC花费的时间的百分比。这个值越高越好
- Latency:延迟情况。这里的延迟情况是指的GC过程花费的时间。具体含义如上图
Interactive Graphs
- GC前后堆空间大小
这里列出了Minor GC 的情况, Full GC的情况, GC停顿统计, 以及总的GC统计
Memory Leak
GC Causes
GC产生的原因分析
- 内存分配失败触发GC的情况统计:
- 元数据空间不足触发GC的情况统计:
- GCLocker启动的GC触发GC的情况统计 :
重磅功能---GC分析后的优化
只可惜是收费的。据说找问题的准确率还是挺高的。