GC日志打印

tuoerke

于 2024-03-22 17:42:14 发布

阅读量598

点赞数 15

分类专栏： jvm 文章标签： jvm

本文链接：https://blog.csdn.net/aoxiaojun/article/details/136947980

版权

jvm 专栏收录该内容

7 篇文章 0 订阅

订阅专栏

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]