JVM日志打印学习笔记

JVM的GC日志的主要参数包括如下几个：

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）

-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

其中由于老大今天让我来规范一下gc的打印，所以研究了一下打印方面的GC日志方面的配置，测试DEMO

public class GCLogTest {
    private static Map<String, String> mapContainer = new HashMap<String, String>();

    /**
     * @param args
     */
    public static void main(String[] args) {

        System.out.println("Java 7 HotSpot Verbose GC Test Program v1.0");
        System.out.println("Author: Pierre-Hugues Charbonneau");
        System.out.println("http://javaeesupportpatterns.blogspot.com/");

        String stringDataPrefix = "stringDataPrefix";

        // Load Java Heap with 3 M java.lang.String instances
        for (int i = 0; i < 3000000; i++) {
            String newStringData = stringDataPrefix + i;
            mapContainer.put(newStringData, newStringData);
        }

        System.out.println("MAP size: " + mapContainer.size());
        System.gc(); // Explicit GC!

        // Remove 2 M out of 3
        for (int i = 0; i < 2000000; i++) {
            String newStringData = stringDataPrefix + i;
            mapContainer.remove(newStringData);
        }

        System.out.println("MAP size: " + mapContainer.size());
        System.gc();
        System.out.println("End of program!");

    }
}

配置信息：-XX:+PrintGC -Xloggc:../gccp.log获取的打印信息是：可以看出-XX:+PrintGC 默认会使用  PrintGCTimeStamps

CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
0.614: [GC (Allocation Failure)  65536K->40248K(251392K), 0.0473919 secs]
0.750: [GC (Allocation Failure)  104088K->102792K(316928K), 0.0847243 secs]
1.064: [GC (Allocation Failure)  233864K->226156K(357376K), 0.1641230 secs]
1.228: [Full GC (Ergonomics)  226156K->216239K(602624K), 1.3260893 secs]
2.693: [GC (Allocation Failure)  347311K->345248K(648704K), 0.2600820 secs]
2.953: [Full GC (Ergonomics)  345248K->344688K(875520K), 1.9544104 secs]
4.958: [GC (System.gc())  372551K->369264K(927744K), 0.0617654 secs]
5.020: [Full GC (System.gc())  369264K->369144K(927744K), 1.8180924 secs]
7.371: [GC (System.gc())  572076K->369176K(917504K), 0.0138325 secs]
7.385: [Full GC (System.gc())  369176K->134847K(917504K), 0.6807835 secs]

配置信息： -XX:+PrintGCTimeStamps -Xloggc:../gccp.log 获取的打印信息是：可以看出-XX:+PrintGCTimeStamps 默认会使用  -XX:+PrintGC -XX:+PrintGCDateStamps

CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDateStamps 

-XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2017-10-12T17:52:07.533-0800: 0.485: [GC (Allocation Failure)  65536K->38184K(251392K), 0.0461476 secs]
2017-10-12T17:52:07.625-0800: 0.577: [GC (Allocation Failure)  102023K->102784K(316928K), 0.0953543 secs]
2017-10-12T17:52:07.895-0800: 0.847: [GC (Allocation Failure)  233856K->242544K(376320K), 0.1174045 secs]
2017-10-12T17:52:08.013-0800: 0.964: [Full GC (Ergonomics)  242544K->216358K(618496K), 0.9463914 secs]
2017-10-12T17:52:09.081-0800: 2.032: [GC (Allocation Failure)  347430K->345366K(671232K), 0.2042709 secs]
2017-10-12T17:52:09.285-0800: 2.236: [Full GC (Ergonomics)  345366K->344683K(883712K), 2.2428295 secs]
2017-10-12T17:52:11.554-0800: 4.505: [GC (System.gc())  369980K->369259K(944640K), 0.0422870 secs]
2017-10-12T17:52:11.596-0800: 4.548: [Full GC (System.gc())  369259K->369143K(944640K), 1.1705959 secs]
2017-10-12T17:52:13.110-0800: 6.062: [GC (System.gc())  576042K->369175K(934400K), 0.0052931 secs]
2017-10-12T17:52:13.115-0800: 6.067: [Full GC (System.gc())  369175K->134846K(934400K), 0.5562611 secs]

配置：-XX:+PrintGCDetail 

CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
0.533: [GC (Allocation Failure) [PSYoungGen: 65536K->10740K(76288K)] 65536K->38200K(251392K), 0.0357648 secs] [Times: user=0.17 sys=0.05, real=0.04 secs] 
0.651: [GC (Allocation Failure) [PSYoungGen: 74579K->10740K(141824K)] 102039K->102804K(316928K), 0.0627379 secs] [Times: user=0.32 sys=0.07, real=0.06 secs] 
0.879: [GC (Allocation Failure) [PSYoungGen: 141812K->10740K(141824K)] 233876K->242564K(374784K), 0.1367007 secs] [Times: user=0.61 sys=0.14, real=0.13 secs] 
1.016: [Full GC (Ergonomics) [PSYoungGen: 10740K->0K(141824K)] [ParOldGen: 231823K->216360K(480256K)] 242564K->216360K(622080K), [Metaspace: 3411K->3411K(1056768K)], 1.0057289 secs] [Times: user=3.27 sys=0.07, real=1.01 secs] 
2.132: [GC (Allocation Failure) [PSYoungGen: 131072K->10752K(188416K)] 347432K->345376K(668672K), 0.2044807 secs] [Times: user=1.36 sys=0.09, real=0.21 secs] 
2.337: [Full GC (Ergonomics) [PSYoungGen: 10752K->0K(188416K)] [ParOldGen: 334624K->344685K(698368K)] 345376K->344685K(886784K), [Metaspace: 3413K->3413K(1056768K)], 2.2767837 secs] [Times: user=15.55 sys=0.25, real=2.27 secs] 
4.640: [GC (System.gc()) [PSYoungGen: 27943K->10752K(239104K)] 372628K->369253K(937472K), 0.0343571 secs] [Times: user=0.20 sys=0.01, real=0.03 secs] 
4.674: [Full GC (System.gc()) [PSYoungGen: 10752K->0K(239104K)] [ParOldGen: 358501K->369145K(698368K)] 369253K->369145K(937472K), [Metaspace: 3413K->3413K(1056768K)], 1.1747250 secs] [Times: user=8.15 sys=0.17, real=1.18 secs] 
6.230: [GC (System.gc()) [PSYoungGen: 206515K->32K(228864K)] 575661K->369177K(927232K), 0.0051389 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
6.235: [Full GC (System.gc()) [PSYoungGen: 32K->0K(228864K)] [ParOldGen: 369145K->134848K(698368K)] 369177K->134848K(927232K), [Metaspace: 3419K->3419K(1056768K)], 0.6952025 secs] [Times: user=3.62 sys=0.09, real=0.70 secs] 
Heap
 PSYoungGen      total 228864K, used 4567K [0x000000076ab00000, 0x000000077b600000, 0x00000007c0000000)
  eden space 228352K, 2% used [0x000000076ab00000,0x000000076af75e00,0x0000000778a00000)
  from space 512K, 0% used [0x000000077b580000,0x000000077b580000,0x000000077b600000)
  to   space 10752K, 0% used [0x000000077a100000,0x000000077a100000,0x000000077ab80000)
 ParOldGen       total 698368K, used 134848K [0x00000006c0000000, 0x00000006eaa00000, 0x000000076ab00000)
  object space 698368K, 19% used [0x00000006c0000000,0x00000006c83b00a8,0x00000006eaa00000)
 Metaspace       used 3426K, capacity 4494K, committed 4864K, reserved 1056768K
  class space    used 363K, capacity 386K, committed 512K, reserved 1048576K

配置：-XX:+PrintGCDateStamps 

CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2017-10-12T17:57:57.681-0800: 0.539: [GC (Allocation Failure)  65536K->38187K(251392K), 0.0394245 secs]
2017-10-12T17:57:57.821-0800: 0.679: [GC (Allocation Failure)  102025K->102803K(316928K), 0.0725128 secs]
2017-10-12T17:57:58.051-0800: 0.909: [GC (Allocation Failure)  233875K->226155K(357376K), 0.1488680 secs]
2017-10-12T17:57:58.200-0800: 1.058: [Full GC (Ergonomics)  226155K->216240K(604672K), 1.0895179 secs]
2017-10-12T17:57:59.418-0800: 2.276: [GC (Allocation Failure)  347312K->345249K(652288K), 0.2624741 secs]
2017-10-12T17:57:59.681-0800: 2.539: [Full GC (Ergonomics)  345249K->344688K(877568K), 1.6390586 secs]
2017-10-12T17:58:01.345-0800: 4.203: [GC (System.gc())  369279K->369264K(931840K), 0.0334312 secs]
2017-10-12T17:58:01.379-0800: 4.236: [Full GC (System.gc())  369264K->369143K(931840K), 1.5833879 secs]
2017-10-12T17:58:03.294-0800: 6.152: [GC (System.gc())  575247K->369175K(921600K), 0.0043649 secs]
2017-10-12T17:58:03.298-0800: 6.156: [Full GC (System.gc())  369175K->134846K(921600K), 0.5587344 secs]

打印出来的日志为：

5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  

5.617（时间戳）: [GC（Young GC） 5.617（时间戳）: [ParNew（使用ParNew作为年轻代的垃圾回收期）: 43296K（年轻代垃圾回收前的大小）->7006K（年轻代垃圾回收以后的大小）(47808K)（年轻代的总大小）, 0.0136826 secs（回收时间）] 44992K（堆区垃圾回收前的大小）->8702K（堆区垃圾回收后的大小）(252608K)（堆区总大小）, 0.0137904 secs（回收时间）] [Times: user=0.03（Young GC用户耗时） sys=0.00（Young GC系统耗时）, real=0.02 secs（Young GC实际耗时）]  

1. -XX:+PrintGCDetails  
2. -XX:+PrintHeapAtGC  
3. -XX:+PrintGCDateStamps  
4. -XX:+PrintTenuringDistribution  

{Heap before GC invocations=1 (full 0):  
 PSYoungGen      total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)  
  eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)  
  from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)  
  to   space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)  
 PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)  
  object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)  
 PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)  
  object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  
2013-05-05T23:16:10.480+0800: 5.228: [GC  
Desired survivor size 22347776 bytes, new threshold 7 (max 15)  
 [PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]   
Heap after GC invocations=1 (full 0):  
 PSYoungGen      total 152896K, used 8319K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)  
  eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)  
  from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)  
  to   space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)  
 PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)  
  object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)  
 PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)  
  object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  
}  

[0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)

这种形式的日志有两种意义： 
当这种日志出现在generation的详细信息里的时候，三个数字在HotSpot里分别称为low_boundary、high、high_boundary。 
low_boundary: reserved space的最低地址边界；通常也跟“low”相等，这是commited space的最低地址边界 
high: commited space的最高地址边界 
high_boundary: reserved space的最高地址边界。 

[low_boundary, high_boundary)范围内的就是reserved space，这个space的大小就是max capacity。 
[low, high)范围内的就是commited space，而这个space的大小就是current capacity（当前容量），简称capacity。 
capacity有可能在一对最小值和最大值之间浮动。最大值就是上面说的max capacity。 

参考配置：

-Xloggc:gc.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

可选配置：

-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=<number of files> -XX:GCLogFileSize=<size>

参考样例：

java -Xloggc:gc.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=128K