ellios's blog

ellios's trivial story.

HotSpot各种GC的输出

| Comments

闲着无事体验下jdk7的一些新特性，先体验下G1，顺手把其他的GC方式也复习下。

用来测试的程序

测试程序 
1
2
3
4
5
6
7
8
9
10
11
12
13
14

package gc;

public class HeapOOM {
    static class OOMObject {

    }

    public static void main(String[] args) {
        List<OOMObject> list = new ArrayList<OOMObject>();
        while(true) {
            list.add(new OOMObject());
        }
    }
}

SerialGC

执行命令如下：

java -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC gc.HeapOOM

输出如下

[GC [DefNew: 6919K->1023K(9216K), 0.0184790 secs] 6919K->4907K(19456K), 0.0185330 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC [DefNew: 9215K->1024K(9216K), 0.0220750 secs] 13099K->10753K(19456K), 0.0221190 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
[GC [DefNew: 8510K->8510K(9216K), 0.0000280 secs][Tenured: 9729K->7736K(10240K), 0.0590890 secs] 18240K->16044K(19456K), [Perm : 2364K->2364K(21248K)], 0.0592060 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
[Full GC [Tenured: 7736K->7730K(10240K), 0.0548170 secs] 16044K->16038K(19456K), [Perm : 2364K->2362K(21248K)], 0.0548950 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]

Parallel GC

执行命令如下：

java -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseParallelGC gc.HeapOOM

输出如下：

[GC [PSYoungGen: 6893K->1017K(9216K)] 6893K->4937K(19456K), 0.0185000 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
[GC [PSYoungGen: 9209K->1008K(9216K)] 13129K->10470K(19456K), 0.0256190 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
[Full GC [PSYoungGen: 1008K->187K(9216K)] [ParOldGen: 9462K->10237K(10240K)] 10470K->10425K(19456K) [PSPermGen: 2367K->2365K(21248K)], 0.2739010 secs] [Times: user=0.34 sys=0.00, real=0.28 secs]

Concurrent Mark Sweep

执行命令如下:

java -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC gc.HeapOOM

输出如下：

[GC [ParNew: 6904K->1024K(9216K), 0.1083590 secs] 6904K->6785K(19456K), 0.1084710 secs] [Times: user=0.15 sys=0.01, real=0.11 secs] 
[GC [ParNew: 9216K->9216K(9216K), 0.0000500 secs][CMS: 5761K->8649K(10240K), 0.0645400 secs] 14977K->13591K(19456K), [CMS Perm : 2365K->2363K(21248K)], 0.0647080 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 
[GC [1 CMS-initial-mark: 8649K(10240K)] 13708K(19456K), 0.0081840 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC [CMS[CMS-concurrent-mark: 0.023/0.023 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
 (concurrent mode failure): 8649K->8649K(10240K), 0.0681890 secs] 13708K->13606K(19456K), [CMS Perm : 2363K->2363K(21248K)], 0.0682770 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
[Full GC [CMS: 10239K->10240K(10240K), 0.0688260 secs] 19455K->17275K(19456K), [CMS Perm : 2366K->2366K(21248K)], 0.0689230 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
[GC [1 CMS-initial-mark: 10240K(10240K)] 17430K(19456K), 0.0111890 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-mark: 0.027/0.027 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 
[Full GC [CMS[CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
 (concurrent mode failure): 10240K->10240K(10240K), 0.0884470 secs] 19412K->19412K(19456K), [CMS Perm : 2366K->2366K(21248K)], 0.0885610 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]

G1

执行命令如下：

java -verbose:gc -Xms20M -Xmx20M -XX:+PrintGCDetails -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC gc.HeapOOM

G1的输出好大一坨,这里就主要描述它的各个阶段，详细的内容就略过了,有兴趣的话，自己测把。

[GC pause (young), 0.07679200 secs]
   [Parallel Time:  76.4 ms]
      [GC Worker Start (ms):  126.0  126.1
       Avg: 126.1, Min: 126.0, Max: 126.1, Diff:   0.1]
      [Ext Root Scanning (ms):  0.8  0.7
       Avg:   0.8, Min:   0.7, Max:   0.8, Diff:   0.1]
      [Update RS (ms):  7.6  8.0
       Avg:   7.8, Min:   7.6, Max:   8.0, Diff:   0.4]
         [Processed Buffers : 3 10
          Sum: 13, Avg: 6, Min: 3, Max: 10, Diff: 7]
      [Scan RS (ms):  18.0  11.1
       Avg:  14.5, Min:  11.1, Max:  18.0, Diff:   6.9]
      [Object Copy (ms):  49.9  56.5
       Avg:  53.2, Min:  49.9, Max:  56.5, Diff:   6.6]
      [Termination (ms):  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1 1
          Sum: 2, Avg: 1, Min: 1, Max: 1, Diff: 0]
      [GC Worker End (ms):  202.4  202.4
       Avg: 202.4, Min: 202.4, Max: 202.4, Diff:   0.0]
      [GC Worker (ms):  76.3  76.2
       Avg:  76.3, Min:  76.2, Max:  76.3, Diff:   0.1]
      [GC Worker Other (ms):  0.1  0.2
       Avg:   0.1, Min:   0.1, Max:   0.2, Diff:   0.1]
   [Clear CT:   0.1 ms]
   [Other:   0.3 ms]
      [Choose CSet:   0.0 ms]
      [Ref Proc:   0.1 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   0.0 ms]
   [Eden: 7168K(7168K)->0B(3072K) Survivors: 0B->1024K Heap: 10138K(20M)->8858K(20M)]
 [Times: user=0.11 sys=0.00, real=0.08 secs] 
[GC pause (young) (initial-mark), 0.05340800 secs] 
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0015220]
[GC concurrent-mark-start]
[GC pause (young), 0.04182800 secs]
[Full GC 13M->10M(20M), 0.0579320 secs]
 [Times: user=0.07 sys=0.00, real=0.06 secs] 
[GC concurrent-mark-abort]
[GC pause (young) (to-space overflow), 0.18594400 secs]
[GC pause (young) (initial-mark), 0.02209700 secs]
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0000130]
[GC concurrent-mark-start]
[Full GC 17M->15M(20M), 0.0831100 secs]
 [Times: user=0.09 sys=0.01, real=0.08 secs] 
[GC pause (young), 0.00407500 secs]
[GC concurrent-mark-abort]
[Full GC 15M->15M(20M), 0.0741120 secs]
 [Times: user=0.08 sys=0.00, real=0.07 secs] 
[Full GC 15M->15M(20M), 0.0801960 secs]
 [Times: user=0.08 sys=0.00, real=0.08 secs]

参考资料

http://blog.csdn.net/firecoder/article/details/7225654

Comments