JavaGC日志格式

不同收集器日志格式不同
不同收集器日志有一些共性
gc日志需要相对应开关控制

GC参数汇总

GC日志参数

-verbose:gc

输出gc详细情况，效果等同于：-XX:+PrintGC

-verbose:gc  
稳定版本  
参见：[官方文档](http://docs.oracle.com/javase/7/docs/technotes/tools/windows/java.html)

-XX:+PrintGC  
非稳定版本，可能在未通知的情况下删除，在下面官方文档中是-XX:-PrintGC。  
因为被标记为manageable，所以可以通过如下三种方式修改：
1. com.sun.management.HotSpotDiagnosticMXBean API
2. JConsole
3. jinfo -flag
参见：[官方文档](http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html)

输出格式：

1
2
3

[GC类型（gc原因）gc前占用空间->gc后占用空间(堆总空间)，gc消耗时间(秒)]
[GC (System.gc())  7891K->1320K(62976K), 0.0018702 secs]
[Full GC (System.gc())  1320K->1202K(62976K), 0.0112032 secs]

-XX:+PrintGCDetails

打印gc详细信息、添加后 -verbose:gc（-XX:+PrintGC）自动失效。

[
    GC类型 (GC原因) 
    [代区域标识：gc前占用空间->gc后占用空间（代总空间） ]
    …… 
    总gc前占用空间->总gc后占用空间（堆空间），
    [元数据空间：gc前占用空间->gc后占用空间（元数据总空间）],gc总消耗时间(秒)]
    [时间分布：用户时间 系统时间 真实消耗时间]
	由于多cpu的原因，用户时间+系统时间≥真实消耗时间

[GC (System.gc()) [PSYoungGen: 9974K->2320K(18944K)] 9974K->3352K(62976K), 0.0075374 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[Full GC (System.gc()) [PSYoungGen: 2320K->0K(18944K)] [ParOldGen: 1032K->3244K(44032K)] 3352K->3244K(62976K), [Metaspace: 5059K->5059K(1056768K)], 0.0083919 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 

内存空间明细：

Heap
 PSYoungGen      total 18944K, used 1524K [0x00000007beb00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 16384K, 9% used [0x00000007beb00000,0x00000007bec7d110,0x00000007bfb00000)
  from space 2560K, 0% used [0x00000007bfb00000,0x00000007bfb00000,0x00000007bfd80000)
  to   space 2560K, 0% used [0x00000007bfd80000,0x00000007bfd80000,0x00000007c0000000)
 ParOldGen       total 44032K, used 795K [0x00000007bc000000, 0x00000007beb00000, 0x00000007beb00000)
  object space 44032K, 1% used [0x00000007bc000000,0x00000007bc0c6e20,0x00000007beb00000)
 Metaspace       used 5370K, capacity 5488K, committed 5632K, reserved 1056768K
  class space    used 619K, capacity 656K, committed 768K, reserved 1048576K

-XX:+PrintGCTimeStamps

最前面增加gc发生时间（jvm启动到gc发生时刻的秒数），其余格式无变化。
同上面两个参数配合使用。

1 2	0.484: [GC (System.gc()) 4960K->3982K(62976K), 0.0014751 secs] 0.485: [Full GC (System.gc()) 3982K->1829K(62976K), 0.0105126 secs]

GC触发原因

“System.gc()”;
“FullGCAlot”;
“ScavengeAlot”;
“Allocation Profiler”;
“JvmtiEnv ForceGarbageCollection”;
“GCLocker Initiated GC”;
“Heap Inspection Initiated GC”;
“Heap Dump Initiated GC”;
“WhiteBox Initiated Young GC”;
“WhiteBox Initiated Concurrent Mark”;
“WhiteBox Initiated Full GC”;
“Update Allocation Context Stats”;
“No GC”;
“Allocation Failure”;
“Tenured Generation Full”;
“Metadata GC Threshold”;
“Metadata GC Clear Soft References”;
“CMS Generation Full”;
“CMS Initial Mark”;
“CMS Final Remark”;
“CMS Concurrent Mark”;
“Old Generation Expanded On Last Scavenge”;
“Old Generation Too Full To Scavenge”;
“Ergonomics”;
“G1 Evacuation Pause”;
“G1 Humongous Allocation”;
“Diagnostic Command”;
“unknown GCCause”;

常见GC触发原因

System.gc()

系统主动调用
示例代码

/**
 * 系统主动调用GC
 * -XX:+PrintGC -XX:PrintGCTimeStamps
 */
@Test
public void sence4() {
    System.gc();
}

GC日志

1 2	0.323: [GC (System.gc()) 8665K->1288K(125952K), 0.0040810 secs] 0.327: [Full GC (System.gc()) 1288K->1202K(125952K), 0.0120565 secs]

GC发生原因：System.gc()

Allocation Failure

Java heap space
PermGen space
MetaData Space

Java Heap Space

/**
     * GC 触发原因：
     * <p>
     * Allocation Failure
     * <p>
     * Java heap space（堆内存不够）
     * <p>
     * -Xmx100m -Xmn100m -XX:+PrintGC -XX:+PrintGCTimeStamps
     */
    @Test
    public void sence5() {
        int _1MB = 1024 * 1024;
        byte[] bigSize = new byte[_1MB * 80];
    }

日志

0.364: [GC (Allocation Failure)  10853K->1384K(90112K), 0.0050521 secs]
0.370: [GC (Allocation Failure)  1384K->1280K(90112K), 0.0028788 secs]
0.372: [Full GC (Allocation Failure)  1280K->1203K(90112K), 0.0110979 secs]
0.384: [Full GC (Allocation Failure)  1203K->1141K(90112K), 0.0052807 secs]
java.lang.OutOfMemoryError: Java heap space