Interpreting G1 GC log

[Timur Akhmadeev]

Hello all,

 

I’m testing an application which is very sensitive to GC pause times. I’ve already tried CMS and found it quite capable of handling Full GC using reasonable pauses; now I want to try G1. The first impression is G1 can defer Full GC, and does it better than CMS. I found it hard to interpret what is logged by G1, so I would like to ask if someone can help me to understand G1 log. I’m using jdk6u16 on OEL4u7 and startup options are following:

 

-XX:+UseLargePages 

-Xms2048m 

-Xmx2048m 

-XX:G1YoungGenSize=1600m 

-XX:+UnlockExperimentalVMOptions 

-XX:+UseG1GC 

-XX:MaxGCPauseMillis=25 

-XX:GCPauseIntervalMillis=5000 

-XX:+G1ParallelRSetUpdatingEnabled 

-XX:+G1ParallelRSetScanningEnabled 

-Xloggc:../logs/gc.log 

-XX:+PrintGCDetails

 

The box has 4 cores, so I assume it is using 4 threads for GC. Here is information about threads related to GC:

 

"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x08061000 nid=0x32b6 runnable

"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x08062400 nid=0x32b7 runnable

"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x08063c00 nid=0x32b8 runnable

"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x08065000 nid=0x32b9 runnable

"G1 concurrent mark GC Thread" prio=10 tid=0x080cb000 nid=0x32bb runnable

"G1 concurrent refinement GC Thread" prio=10 tid=0x080a6800 nid=0x32ba runnable

"G1 zero-fill GC Thread" prio=10 tid=0x0810e800 nid=0x32bd runnable

 

And here is an excerpt of one minor collection:

 

1900.742: [GC pause (young), 0.08446400 secs]

   [Parallel Time:  65.5 ms]

      [Update RS (Start) (ms):  1900759.4  1900754.3  1900754.6  1900754.1]

      [Update RS (ms):  2.7  0.7  0.4  0.9

       Avg:   1.2, Min:   0.4, Max:   2.7]

         [Processed Buffers : 0 20 8 18

          Sum: 46, Avg: 11, Min: 0, Max: 20]

      [Ext Root Scanning (ms):  8.9  4.7  5.9  5.4

       Avg:   6.3, Min:   4.7, Max:   8.9]

      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0

       Avg:   0.0, Min:   0.0, Max:   0.0]

      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0

       Avg:   0.0, Min:   0.0, Max:   0.0]

         [Scan-Only Regions : 0 0 0 0

          Sum: 0, Avg: 0, Min: 0, Max: 0]

      [Scan RS (ms):  0.3  3.8  3.7  3.7

       Avg:   2.9, Min:   0.3, Max:   3.8]

      [Object Copy (ms):  48.4  50.6  48.8  51.8

       Avg:  49.9, Min:  48.4, Max:  51.8]

      [Termination (ms):  1.7  5.5  4.7  1.7

       Avg:   3.4, Min:   1.7, Max:   5.5]

      [Other:   1.9 ms]

   [Clear CT:   2.8 ms]

   [Other:  16.2 ms]

   [ 1827M->247M(2048M)]

 [Times: user=0.26 sys=0.01, real=0.09 secs] 

 

Here’re my questions:

 

1)       GC pause (young), 0.08195600 secs

Does it mean that the application was stopped for 0.0819 seconds? If so, what is represented by this line:

[Times: user=0.26 sys=0.01, real=0.09 secs]

2)       What parts of G1 are working in parallel/serially?

3)       What parts of G1 are working concurrently/cause stop-the-world?

 

BTW, I found that large pages are not working with G1 – JVM silently uses usual way for OS memory allocation. Is it a bug?

 

TIA,

Timur Akhmadeev

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20091016/8d8f9f9c/attachment-0001.html