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实际耗时)]
- -XX:+PrintGCDetails
- -XX:+PrintHeapAtGC
- -XX:+PrintGCDateStamps
- -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。
可选配置:
-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