JavaVM
JVM

理解GC日志

对于Java应用可以通过一些配置把程序运行过程中的GC日志全部打印出来，然后分析GC日志得到关键性指标，分析GC原因，调优JVM参数。打印GC日志方法，在JVM参数里增加参数，%t 代表时间，最多生成10个日志文件，每个文件最大100M，滚动刷新；Tomcat则直接加在JAVA_OPTS变量里：

1
-Xloggc:./gc‐%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M

但若GC日志非常多，很难凭肉眼分析，可以借助一些功能来帮助分析，这里推荐一个gceasy，上传GC文件，可以利用可视化的界面来展现GC情况。

阅读GC日志是处理Java虚拟机内存问题的基础技能，每一种收集器的日志形式都是由他们自身的实现所决定的，所以每个收集器的日志格式都可以不一样，但虚拟机设计者为了方便用户阅读，将各个收集器的日志都维持一定的共性。下面是一段GC日志：

1
2
3
4
5
6
7
[GC [PSYoungGen: 23552K->3581K(27136K)] 23552K->16249K(88576K), 0.0185611 secs] [Times: user=0.08 sys=0.02, real=0.02 secs] 
[GC [PSYoungGen: 27133K->3560K(27136K)] 39801K->31030K(88576K), 0.0323523 secs] [Times: user=0.11 sys=0.01, real=0.03 secs] 
[GC [PSYoungGen: 27112K->3568K(27136K)] 54582K->54585K(88576K), 0.0363496 secs] [Times: user=0.16 sys=0.02, real=0.04 secs] 
[Full GC [PSYoungGen: 3568K->0K(27136K)] [ParOldGen: 51017K->47268K(61440K)] 54585K->47268K(88576K) [PSPermGen: 3169K->3168K(21504K)], 0.5726540 secs] [Times: user=1.78 sys=0.01, real=0.57 secs] 
[Full GC [PSYoungGen: 23552K->0K(27136K)] [ParOldGen: 47268K->60136K(61440K)] 70820K->60136K(88576K) [PSPermGen: 3168K->3168K(21504K)], 0.3987444 secs] [Times: user=1.41 sys=0.02, real=0.40 secs] 
[Full GC [PSYoungGen: 20624K->19567K(27136K)] [ParOldGen: 60136K->61132K(61440K)] 80761K->80700K(88576K) [PSPermGen: 3168K->3168K(21504K)], 0.8462723 secs] [Times: user=3.38 sys=0.05, real=0.85 secs] 
[Full GC [PSYoungGen: 19567K->19567K(27136K)] [ParOldGen: 61132K->61116K(61440K)] 80700K->80684K(88576K) [PSPermGen: 3168K->3168K(21504K)], 0.4721533 secs] [Times: user=2.83 sys=0.03, real=0.47 secs]

GC日志开头的[GC和[Full GC说明这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC。如果是调用System.gc()方法所触发的收集，这里就将显示[Full GC（System）。

接下来的[PSYoungGen、[ParOldGen、[PSPermGen表是GC发生的区域，区域名称与使用的GC收集器是密切相关的。

后面方括号内的23552K->3581K(27136K)表示GC前该内存区域已使用容量->GC后该内存区域已使用容量（该内存区域总容量）

方括号外的23552K->16249K(88576K)表示GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）

0.0185611 secs表示该内存区域GC所占用的时间，单位秒。[Times: user=0.08 sys=0.02, real=0.02 secs]更具体的时间数据，这里的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间。

JVM参数汇总查看命令

java -XX:+PrintFlagsInitial：打印出所有参数选项的默认值
java -XX:+PrintFlagsFinal：打印出所有参数选项在运行程序时生效的值

Serial & Serial Old GC日志

1
2
3
4
5
6
[GC[DefNew: 24234K->3072K(27648K), 0.0279728 secs] 24234K->16411K(89088K), 0.0280186 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
[GC[DefNew: 27648K->3072K(27648K), 0.0348831 secs] 40987K->35255K(89088K), 0.0349111 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
[GC[DefNew: 27648K->3072K(27648K), 0.0420056 secs] 59831K->59830K(89088K), 0.0420333 secs] [Times: user=0.05 sys=0.00, real=0.04 secs] 
[GC[DefNew: 27648K->27648K(27648K), 0.0000186 secs][Tenured: 56758K->61440K(61440K), 0.1322486 secs] 84406K->63429K(89088K), [Perm : 3169K->3169K(21248K)], 0.1323137 secs] [Times: user=0.14 sys=0.00, real=0.13 secs] 
[Full GC[Tenured: 61440K->61440K(61440K), 0.1457481 secs] 80851K->80700K(89088K), [Perm : 3169K->3169K(21248K)], 0.1457820 secs] [Times: user=0.16 sys=0.00, real=0.14 secs] 
[Full GC[Tenured: 61440K->61440K(61440K), 0.1661660 secs] 80700K->80684K(89088K), [Perm : 3169K->3168K(21248K)], 0.1661913 secs] [Times: user=0.16 sys=0.00, real=0.17 secs]

[DefNew、[Tenured、[Perm分别表示年轻代、老年代和永久代。

ParNew & serial Old GC日志

1
2
3
4
5
6
[GC[ParNew: 24234K->3072K(27648K), 0.0240967 secs] 24234K->16475K(89088K), 0.0241453 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
[GC[ParNew: 27648K->3072K(27648K), 0.0361463 secs] 41051K->35736K(89088K), 0.0362102 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
[GC[ParNew: 27648K->3072K(27648K), 0.0369859 secs] 60312K->60003K(89088K), 0.0370325 secs] [Times: user=0.23 sys=0.00, real=0.04 secs] 
[GC[ParNew: 27648K->27648K(27648K), 0.0000158 secs][Tenured: 56931K->61440K(61440K), 0.1430511 secs] 84579K->63429K(89088K), [Perm : 3169K->3169K(21248K)], 0.1431067 secs] [Times: user=0.14 sys=0.00, real=0.14 secs] 
[Full GC[Tenured: 61440K->61440K(61440K), 0.1444908 secs] 80851K->80700K(89088K), [Perm : 3169K->3169K(21248K)], 0.1445358 secs] [Times: user=0.14 sys=0.00, real=0.14 secs] 
[Full GC[Tenured: 61440K->61440K(61440K), 0.1710500 secs] 80700K->80684K(89088K), [Perm : 3169K->3168K(21248K)], 0.1710760 secs] [Times: user=0.17 sys=0.00, real=0.17 secs]

[ParNew、[Tenured、[Perm分别表示年轻代、老年代和永久代。

ParNew & CMS（serial old为替补）GC日志

1
-Xloggc:d:/gc‐cms‐%t.log -Xms50M -Xmx50M -‐XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC
1
2
3
4
5
6
7
[GC[ParNew: 23938K->3072K(27648K), 0.0849733 secs] 23938K->21528K(89088K), 0.0850416 secs] [Times: user=0.53 sys=0.02, real=0.09 secs] 
[GC[ParNew: 27648K->3072K(27648K), 0.0363515 secs] 46104K->45931K(89088K), 0.0363863 secs] [Times: user=0.22 sys=0.05, real=0.04 secs] 
[GC [1 CMS-initial-mark: 42859K(61440K)] 46267K(89088K), 0.0020835 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 27648K->27648K(27648K), 0.0000146 secs][CMS[CMS-concurrent-mark: 0.132/0.133 secs] [Times: user=0.17 sys=0.06, real=0.13 secs] 
 (concurrent mode failure): 42859K->61439K(61440K), 0.2594182 secs] 70507K->66264K(89088K), [CMS Perm : 3170K->3169K(21248K)], 0.2594711 secs] [Times: user=0.31 sys=0.06, real=0.26 secs] 
[Full GC[CMS: 61439K->61439K(61440K), 0.1218246 secs] 71016K->70720K(89088K), [CMS Perm : 3169K->3169K(21248K)], 0.1218598 secs] [Times: user=0.13 sys=0.00, real=0.12 secs] 
[Full GC[CMS: 61439K->61440K(61440K), 0.1510773 secs] 70720K->70709K(89088K), [CMS Perm : 3169K->3169K(21248K)], 0.1511120 secs] [Times: user=0.14 sys=0.00, real=0.15 secs]

[ParNew、[CMS、[Perm分别表示年轻代、老年代和永久代。其中(concurrent mode failure)表示CMS收集器无法处理浮动垃圾，出现了Concurrent Mode Failure失败而导致另一次Full GC产生，这时虚拟机就会启动后备预案，临时使用Serial Old收集器来重新进行老年代的垃圾收集。

Parallel Scavenge & Parallel Old GC日志

1
2
3
4
5
6
7
[GC [PSYoungGen: 23552K->3581K(27136K)] 23552K->16249K(88576K), 0.0185611 secs] [Times: user=0.08 sys=0.02, real=0.02 secs] 
[GC [PSYoungGen: 27133K->3560K(27136K)] 39801K->31030K(88576K), 0.0323523 secs] [Times: user=0.11 sys=0.01, real=0.03 secs] 
[GC [PSYoungGen: 27112K->3568K(27136K)] 54582K->54585K(88576K), 0.0363496 secs] [Times: user=0.16 sys=0.02, real=0.04 secs] 
[Full GC [PSYoungGen: 3568K->0K(27136K)] [ParOldGen: 51017K->47268K(61440K)] 54585K->47268K(88576K) [PSPermGen: 3169K->3168K(21504K)], 0.5726540 secs] [Times: user=1.78 sys=0.01, real=0.57 secs] 
[Full GC [PSYoungGen: 23552K->0K(27136K)] [ParOldGen: 47268K->60136K(61440K)] 70820K->60136K(88576K) [PSPermGen: 3168K->3168K(21504K)], 0.3987444 secs] [Times: user=1.41 sys=0.02, real=0.40 secs] 
[Full GC [PSYoungGen: 20624K->19567K(27136K)] [ParOldGen: 60136K->61132K(61440K)] 80761K->80700K(88576K) [PSPermGen: 3168K->3168K(21504K)], 0.8462723 secs] [Times: user=3.38 sys=0.05, real=0.85 secs] 
[Full GC [PSYoungGen: 19567K->19567K(27136K)] [ParOldGen: 61132K->61116K(61440K)] 80700K->80684K(88576K) [PSPermGen: 3168K->3168K(21504K)], 0.4721533 secs] [Times: user=2.83 sys=0.03, real=0.47 secs]

[PSYoungGen、[ParOldGen、[PSPermGen分别表示年轻代、老年代和永久代。

G1 收集器

1
-Xloggc:d:/gc‐g1‐%t.log -Xms50M -Xmx50M -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M -XX:+UseG1GC
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
[GC pause (young) (initial-mark), 0.0089815 secs]
   [Parallel Time: 8.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1992.2, Avg: 1992.3, Max: 1992.3, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.3, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.5]
      [Update RS (ms): Min: 2.2, Avg: 2.8, Max: 3.8, Diff: 1.6, Sum: 22.8]
         [Processed Buffers: Min: 4, Avg: 4.9, Max: 6, Diff: 2, Sum: 39]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 4.5, Avg: 5.4, Max: 6.0, Diff: 1.6, Sum: 43.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 8.6, Avg: 8.6, Max: 8.6, Diff: 0.1, Sum: 68.7]
      [GC Worker End (ms): Min: 2000.8, Avg: 2000.8, Max: 2000.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(3072.0K)->0.0B(3072.0K) Survivors: 1024.0K->1024.0K Heap: 79.0M(90.0M)->81.8M(90.0M)]
 [Times: user=0.13 sys=0.00, real=0.01 secs] 
[GC concurrent-root-region-scan-start]
[GC pause (young)[GC concurrent-root-region-scan-end, 0.0001366 secs]
[GC concurrent-mark-start], 0.0030254 secs]
   [Root Region Scan Waiting: 0.1 ms]
   [Parallel Time: 2.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 2001.5, Avg: 2001.5, Max: 2001.5, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.3, Avg: 0.3, Max: 0.4, Diff: 0.1, Sum: 2.7]
      [SATB Filtering (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Update RS (ms): Min: 1.1, Avg: 1.3, Max: 1.9, Diff: 0.8, Sum: 10.6]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 4, Diff: 2, Sum: 22]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.3, Avg: 0.8, Max: 1.1, Diff: 0.8, Sum: 6.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.5, Avg: 2.5, Max: 2.6, Diff: 0.0, Sum: 20.3]
      [GC Worker End (ms): Min: 2004.0, Avg: 2004.0, Max: 2004.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 0.0B(3072.0K)->0.0B(4096.0K) Survivors: 1024.0K->0.0B Heap: 81.8M(90.0M)->81.6M(90.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC 81M->78M(90M), 0.1786909 secs]
   [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 81.6M(90.0M)->78.8M(90.0M)]
 [Times: user=0.28 sys=0.00, real=0.18 secs] 
[Full GC 78M->78M(90M), 0.1693387 secs]
   [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 78.8M(90.0M)->78.8M(90.0M)]
 [Times: user=0.17 sys=0.00, real=0.17 secs]

垃圾收集器参数

参数 描述
UseSerialGC 使用Serial & Serial Old收集器（client模式默认值）
UseParNewGC 使用ParNew & Serial Old收集器（不推荐）
UseConcMarkSweepGC 使用ParNew & CMS（Serial Old为替补）收集器
UseParallelGC 使用Parallel Scavenge & Parallel Old收集器（Server模式默认值）
UseParallelOldGC 在年老代使用Parallel Old收集器
UseG1GC 使用G1收集器