本系列笔记主要基于《深入理解Java虚拟机:JVM高级特性与最佳实践 第2版》,是这本书的读书笔记。
收集GC日志不同的垃圾收集器,输出的日志格式各不相同,但也有一些相同的特征。熟悉各个常用垃圾收集器的GC日志,是进行JVM调优的必备一步。
解析GC日志,首先需要收集日志,常用的有以下JVM参数用来打印输出日志信息:
-XX:+PrintGCDetails 打印GC详细信息
-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式)
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-XX:+PrintTenuringDistribution 在进行GC时打印survivor中的对象年龄分布信息
-Xloggc:$CATALINA_HOME/logs/gc.log 指定输出路径收集日志到日志文件
例如,我使用如下参数启动:
-Xms28m -Xmx28m -XX:PermSize=14M -XX:MaxNewSize=14m -XX:MaxPermSize=14m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:E:/logs/gc.log如果要指定垃圾收集器,还需要添加对应的JVM参数,例如-XX:+UseG1GC、-XX:+UseConcMarkSweepGC等
-XX:+UseParallelGC日志解析JDK1.8的默认收集器为Parallel收集器+Serial Old收集器组合(-XX:+UseParallelGC),日志如下:
Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010) Memory: 4k page, physical 8303556k(2789672k free), swap 16215992k(6967912k free) CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 2018-05-08T19:23:01.815+0800: 0.574: [GC (Allocation Failure) [PSYoungGen: 11264K->1531K(12800K)] 11264K->2283K(27136K), 0.0039021 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:23:01.906+0800: 0.664: [GC (System.gc()) [PSYoungGen: 6560K->1516K(12800K)] 7311K->2625K(27136K), 0.0030390 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:23:01.908+0800: 0.667: [Full GC (System.gc()) [PSYoungGen: 1516K->0K(12800K)] [ParOldGen: 1109K->2005K(14336K)] 2625K->2005K(27136K), [Metaspace: 5955K->5955K(1056768K)], 0.0102082 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 2018-05-08T19:23:01.954+0800: 0.714: [GC (Allocation Failure) [PSYoungGen: 11263K->64K(12800K)] 13269K->2069K(27136K), 0.0005071 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:23:01.988+0800: 0.748: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(12800K)] 13333K->2069K(27136K), 0.0003509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:23:02.019+0800: 0.779: [GC (Allocation Failure) [PSYoungGen: 11328K->128K(12800K)] 13333K->2133K(27136K), 0.0003730 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:23:02.049+0800: 0.809: [GC (Allocation Failure) [PSYoungGen: 11391K->64K(9728K)] 13397K->2077K(24064K), 0.0003454 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:24:28.365+0800: 87.124: [GC (System.gc()) [PSYoungGen: 306K->32K(11264K)] 2320K->2045K(25600K), 0.0005228 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-08T19:24:28.365+0800: 87.124: [Full GC (System.gc()) [PSYoungGen: 32K->0K(11264K)] [ParOldGen: 2013K->1706K(14336K)] 2045K->1706K(25600K), [Metaspace: 6027K->6021K(1056768K)], 0.0135435 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] Heap PSYoungGen total 11264K, used 324K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000) eden space 8192K, 3% used [0x00000000ff200000,0x00000000ff2513a0,0x00000000ffa00000) from space 3072K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x00000000ffd00000) to space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000) ParOldGen total 14336K, used 1706K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000) object space 14336K, 11% used [0x00000000fe400000,0x00000000fe5aa8f8,0x00000000ff200000) Metaspace used 6032K, capacity 6242K, committed 6400K, reserved 1056768K class space used 688K, capacity 756K, committed 768K, reserved 1048576K第三行把当前使用的JVM参数打印了出来,初始化了堆大小,设置了最大堆,最后打印出来GC参数-XX:+UseParallelGC。
第四行开始是垃圾收集记录,首先是垃圾收集的时间。然后是发生GC的原因,GC (Allocation Failure)对象分配失败,GC表示新生代Young区的GC,Full GC则包含老年代。[PSYoungGen: 11264K->1531K(12800K)]表示Young区回收前大小是11264K,回收后是1531K,总大小是12800K。紧接着中括号外,11264K->2283K(27136K)表示回收前整个堆大小是11264K,回收后堆大小2283K,堆总大小27136K。0.0039021 secs是垃圾回收用的时间。可以看出,新生代由11M变为了约1.5M,而整个堆由11M变为了约2.2M,也就是这次GC后,老年代约为0.7M。
后面的格式都是类似的,再看第六行Full GC的日志。