GC日志打印

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 可以看到所有的FULL GC已经没有了,时间节省上面,大于是 0.03*3 约等于 0.1秒。

GC日志打印


java -jar -Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX: +UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M xxxxxx.jar

%t 当前时间戳


-Xloggc:./gc-%t.log: 将日志记录到当前路径下,命名为gc-时间戳.log,也可以写绝对路径


-XX:+PrintGCDetails: 打印GC详细日志


-XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps: 打印带时间的GC日志


-XX:+PrintGCCause: 打印GC原因


-XX: +UseGCLogFileRotation: 用于控制GC(垃圾收集)日志文件的滚动记录功能。当GC日志文件的内容达到一定的大小或数量时,该功能可以自动滚动到新的日志文件,以避免单个日志文件过大


-XX:NumberOfGCLogFiles=10: 用于指定滚动的GC日志文件的最大数量


-XX:GCLogFileSize=100M: 指定每个GC日志文件的大小限制。


详细的GC日志参考(parallel垃圾收集器):



Java HotSpot(TM) 64-Bit Server VM (25.261-b12) for windows-amd64 JRE (1.8.0_261-b12), built on Jun 18 2020 06:56:32 by "" with unknown MS VC++:1916
Memory: 4k page, physical 33387572k(11533820k free), swap 37205432k(7288752k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:GCLogFileSize=104857600 -XX:InitialHeapSize=534201152 -XX:+ManagementServer -XX:MaxHeapSize=8547218432 -XX:NumberOfGCLogFiles=10 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 

//Allocation Failure:表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了
2024-03-21T16:16:40.747+0800: 1.793: [GC (Allocation Failure) [PSYoungGen: 131072K->10594K(152576K)] 131072K->10682K(500736K), 0.0078576 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:40.913+0800: 1.958: [GC (Metadata GC Threshold) [PSYoungGen: 51045K->8678K(152576K)] 51133K->8774K(500736K), 0.0071735 secs] [Times: user=0.13 sys=0.02, real=0.01 secs] 
2024-03-21T16:16:40.920+0800: 1.966: [Full GC (Metadata GC Threshold) [PSYoungGen: 8678K->0K(152576K)] [ParOldGen: 96K->8381K(195072K)] 8774K->8381K(347648K), [Metaspace: 20308K->20303K(1067008K)], 0.0322834 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 
2024-03-21T16:16:41.442+0800: 2.488: [GC (Allocation Failure) [PSYoungGen: 131072K->10937K(152576K)] 139453K->19326K(347648K), 0.0040354 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:42.041+0800: 3.086: [GC (Allocation Failure) [PSYoungGen: 142009K->13765K(215552K)] 150398K->22163K(410624K), 0.0069713 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:42.406+0800: 3.451: [GC (Metadata GC Threshold) [PSYoungGen: 78119K->13287K(218112K)] 86517K->21692K(413184K), 0.0066526 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:42.412+0800: 3.458: [Full GC (Metadata GC Threshold) [PSYoungGen: 13287K->0K(218112K)] [ParOldGen: 8405K->19134K(305664K)] 21692K->19134K(523776K), [Metaspace: 33971K->33971K(1079296K)], 0.0317375 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2024-03-21T16:16:43.262+0800: 4.308: [GC (Allocation Failure) [PSYoungGen: 196608K->12883K(296448K)] 215742K->32025K(602112K), 0.0082189 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:43.996+0800: 5.042: [GC (Allocation Failure) [PSYoungGen: 296019K->7883K(308736K)] 315161K->27033K(614400K), 0.0050205 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-03-21T16:16:44.782+0800: 5.828: [GC (Allocation Failure) [PSYoungGen: 300747K->7979K(413184K)] 319897K->27137K(718848K), 0.0053465 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-03-21T16:16:47.402+0800: 8.448: [GC (Allocation Failure) [PSYoungGen: 405291K->13382K(413184K)] 424449K->32548K(718848K), 0.0169885 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2024-03-21T16:16:49.102+0800: 10.148: [GC (Allocation Failure) [PSYoungGen: 410694K->16375K(492544K)] 429860K->40963K(798208K), 0.0115215 secs] [Times: user=0.03 sys=0.02, real=0.01 secs] 
2024-03-21T16:16:49.669+0800: 10.715: [GC (Metadata GC Threshold) [PSYoungGen: 244794K->19939K(496128K)] 269381K->47391K(801792K), 0.0108368 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:49.681+0800: 10.726: [Full GC (Metadata GC Threshold) [PSYoungGen: 19939K->0K(496128K)] [ParOldGen: 27451K->40617K(440320K)] 47391K->40617K(936448K), [Metaspace: 56633K->56633K(1101824K)], 0.1811990 secs] [Times: user=0.42 sys=0.00, real=0.18 secs] 
2024-03-21T16:16:51.139+0800: 12.185: [GC (Allocation Failure) [PSYoungGen: 476160K->13510K(584704K)] 516777K->54135K(1025024K), 0.0088195 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:52.318+0800: 13.363: [GC (Allocation Failure) [PSYoungGen: 584390K->22496K(600064K)] 625015K->66950K(1040384K), 0.0124082 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:16:53.152+0800: 14.198: [GC (Allocation Failure) [PSYoungGen: 600032K->26080K(704000K)] 644486K->78800K(1144320K), 0.0139680 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
2024-03-21T16:16:54.131+0800: 15.177: [GC (Allocation Failure) [PSYoungGen: 703968K->32754K(710656K)] 756688K->91130K(1150976K), 0.0161611 secs] [Times: user=0.00 sys=0.01, real=0.02 secs] 
2024-03-21T16:19:23.778+0800: 164.824: [GC (Allocation Failure) [PSYoungGen: 710642K->38899K(847872K)] 769018K->114757K(1288192K), 0.0253218 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]

young GC,回收前大小131072K,回收后10594K,152576K是总的容量,花费时间0.0078576秒


[GC (Allocation Failure) [PSYoungGen: 131072K->10594K(152576K)] 131072K->10682K(500736K), 0.0078576 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 


第一次FULL GC,原因是metadata GC threadhold,元空间大小达到阈值,元空间在不设置的情况下,初始大小是21M,花费时间0.032 秒


[Full GC (Metadata GC Threshold) [PSYoungGen: 8678K->0K(152576K)] [ParOldGen: 96K->8381K(195072K)] 8774K->8381K(347648K), [Metaspace: 20308K->20303K(1067008K)], 0.0322834 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 


第二次FULL GC,由于元空间大小的动态伸缩机制,扩容到33M左右,当达到阈值,又会进行一次FULL GC。第三次原因一样。


[Full GC (Metadata GC Threshold) [PSYoungGen: 13287K->0K(218112K)] [ParOldGen: 8405K->19134K(305664K)] 21692K->19134K(523776K), [Metaspace: 33971K->33971K(1079296K)], 0.0317375 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 

配置元空间初始化参数大小,可以防止三次FULL GC,因为元空间在所有类加载完成后,大小基本不会发生太大变化。而项目启动后,元空间大小大约在100M左右,所以可以配置-XX:MetaspaceSize=128M,-XX:MaxMetaspaceSize=128m,


再次执行

java -jar -Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX: +UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M -XX:MetaspaceSize=128M,-XX:MaxMetaspaceSize=128m xxxxxx.jar

后的gc日志如下

Java HotSpot(TM) 64-Bit Server VM (25.261-b12) for windows-amd64 JRE (1.8.0_261-b12), built on Jun 18 2020 06:56:32 by "" with unknown MS VC++:1916
Memory: 4k page, physical 33387572k(11482256k free), swap 36877024k(6925536k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:CompressedClassSpaceSize=260046848 -XX:GCLogFileSize=104857600 -XX:InitialHeapSize=534201152 -XX:+ManagementServer -XX:MaxHeapSize=8547218432 -XX:MaxMetaspaceSize=268435456 -XX:MetaspaceSize=268435456 -XX:NumberOfGCLogFiles=10 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2024-03-21T16:23:39.842+0800: 1.853: [GC (Allocation Failure) [PSYoungGen: 131072K->10888K(152576K)] 131072K->10977K(500736K), 0.0082953 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:40.245+0800: 2.257: [GC (Allocation Failure) [PSYoungGen: 141960K->16711K(152576K)] 142049K->16815K(500736K), 0.0111631 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:40.837+0800: 2.849: [GC (Allocation Failure) [PSYoungGen: 147783K->18470K(152576K)] 147887K->18590K(500736K), 0.0104231 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:41.584+0800: 3.595: [GC (Allocation Failure) [PSYoungGen: 149542K->21490K(283648K)] 149662K->23503K(631808K), 0.0138405 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:42.595+0800: 4.607: [GC (Allocation Failure) [PSYoungGen: 283634K->21491K(283648K)] 285647K->29735K(631808K), 0.0159962 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
2024-03-21T16:23:43.288+0800: 5.300: [GC (Allocation Failure) [PSYoungGen: 283635K->22114K(555008K)] 291879K->30365K(903168K), 0.0105527 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:44.632+0800: 6.644: [GC (Allocation Failure) [PSYoungGen: 546402K->14009K(555520K)] 554653K->30838K(903680K), 0.0114409 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:46.750+0800: 8.761: [GC (Allocation Failure) [PSYoungGen: 538297K->23742K(1079296K)] 555126K->47877K(1427456K), 0.0145524 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-03-21T16:23:49.515+0800: 11.527: [GC (Allocation Failure) [PSYoungGen: 1071806K->31720K(1079808K)] 1095941K->70392K(1427968K), 0.0220429 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
2024-03-21T16:23:51.142+0800: 13.154: [GC (Allocation Failure) [PSYoungGen: 1079784K->41445K(1709568K)] 1118456K->91182K(2057728K), 0.0211497 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 


可以看到所有的FULL GC已经没有了,时间节省上面,大于是 0.03*3 约等于 0.1秒。

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
19天前
|
存储 监控 Java
JVM进阶调优系列(8)如何手把手,逐行教她看懂GC日志?| IT男的专属浪漫
本文介绍了如何通过JVM参数打印GC日志,并通过示例代码展示了频繁YGC和FGC的场景。文章首先讲解了常见的GC日志参数,如`-XX:+PrintGCDetails`、`-XX:+PrintGCDateStamps`等,然后通过具体的JVM参数和代码示例,模拟了不同内存分配情况下的GC行为。最后,详细解析了GC日志的内容,帮助读者理解GC的执行过程和GC处理机制。
|
1月前
|
Arthas 监控 Java
JVM知识体系学习七:了解JVM常用命令行参数、GC日志详解、调优三大方面(JVM规划和预调优、优化JVM环境、JVM运行出现的各种问题)、Arthas
这篇文章全面介绍了JVM的命令行参数、GC日志分析以及性能调优的各个方面,包括监控工具使用和实际案例分析。
45 3
|
1月前
|
存储 数据可视化 安全
一个简单案例,带你看懂GC日志!
一个简单案例,带你看懂GC日志!
一个简单案例,带你看懂GC日志!
|
4月前
|
算法 安全 Java
(七)JVM成神路之GC分代篇:分代GC器、CMS收集器及YoungGC、FullGC日志剖析
在《GC基础篇》中曾谈到过分代以及分区回收的概念,但基础篇更多的是建立在GC的一些算法理论上进行高谈阔论,而本篇则重点会对于分代收集器的实现进行全面详解,其中会涵盖串行收集器、并行收集器、三色标记、SATB算法、GC执行过程、并发标记、CMS收集器等知识,本篇则偏重于分析GC机制的落地实现,也就是垃圾收集器(Garbage Collector)。
111 8
|
6月前
|
运维 监控 数据可视化
九、GC收集日志
九、GC收集日志
69 4
九、GC收集日志
|
6月前
|
算法 Java
深入理解JVM - 解读GC日志
深入理解JVM - 解读GC日志
92 0
|
6月前
|
存储 Java
jvm性能调优实战 - 23 模拟Young GC的发生及分析GC日志
jvm性能调优实战 - 23 模拟Young GC的发生及分析GC日志
106 0
|
Java
JVM学习笔记-如何在IDEA打印JVM的GC日志信息
若要在Idea上打印JVM相应GC日志,其实只需在Run/Debug Configurations上进行设置即可。
114 0
|
缓存 安全 Java
JVM中垃圾回收相关参数介绍:大页和NUMA参数+GC日志相关参数
大页和NUMA参数 本节介绍JVM为使用OS而提供的大页和NUMA特性相关的参数。 该参数控制JVM向OS请求内存时使用大页的粒度。使用该参数时需要对OS进行配置,只有OS允许时才能真正启动。参数的默认值与平台相关,一般为false。 在允许使用大页方式向OS请求内存时,如果堆空间小于该阈值,则强制禁止大页使用。该参数的默认值为128MB。 在允许使用大页方式向OS请求内存时,优先在本地节点进行分配。该参数仅适用于Windows系统。 在允许使用大页方式向OS请求内存时,如果OS提供了多种大页的设置,可通过该参数选择其中的大页设置。参数的默认值为0,表示使用OS默认的大页设置。
178 0
|
Java Shell Perl
从 test.log 中截取当天的所有 gc 信息日志,并统计 gc 时间的平均值和时长最长的时间
从 test.log 中截取当天的所有 gc 信息日志,并统计 gc 时间的平均值和时长最长的时间
110 1