AW: G1 GC - pauses much larger than target

[YU ZHANG]

Kirti,

Sorry for the late response.

I think there is a bug in gc log reporting the gc pause time(marked in 
read in the following log). There was a bug filed
https://bugs.openjdk.java.net/browse/JDK-7178365
Basically the time is just parallel gc time, not the whole young gc 
pause time.

After parallel phase, there are some sequential operations(marked in 
green in the gc logs).  Though each step does not take a long time, but 
gc threads could be swapped out during these operations.

One question I have, is why system cpu is 0?  Maybe Linux does not use 
much cpu when swapping?

2014-02-20T02:15:42.580+0000: 14840.246: Application time: 8.5619840 seconds
2014-02-20T02:15:42.581+0000: 14840.247: [GC pause (young)
Desired survivor size 83886080 bytes, new threshold 15 (max 15)
- age   1:    2511184 bytes,    2511184 total
- age   2:    1672024 bytes,    4183208 total
- age   3:    1733824 bytes,    5917032 total
- age   4:    1663920 bytes,    7580952 total
- age   5:    1719944 bytes,    9300896 total
- age   6:    1641904 bytes,   10942800 total
- age   7:    1796976 bytes,   12739776 total
- age   8:    1706344 bytes,   14446120 total
- age   9:    1722920 bytes,   16169040 total
- age  10:    1729176 bytes,   17898216 total
- age  11:    1500056 bytes,   19398272 total
- age  12:    1486520 bytes,   20884792 total
- age  13:    1618272 bytes,   22503064 total
- age  14:    1492840 bytes,   23995904 total
- age  15:    1486920 bytes,   25482824 total
  14840.247: [G1Ergonomics (CSet Construction) start choosing CSet, 
_pending_cards: 12196, predicted base time: 7.85 ms, remaining time: 
17.15 ms, target pause time: 25.00 ms]
  14840.247: [G1Ergonomics (CSet Construction) add young regions to 
CSet, eden: 146 regions, survivors: 7 regions, predicted young region 
time: 8.76 ms]
  14840.247: [G1Ergonomics (CSet Construction) finish choosing CSet, 
eden: 146 regions, survivors: 7 regions, old: 0 regions, predicted pause 
time: 16.60 ms, target pause time: 25.00 ms]
, 0.0247660 secs]
    [Parallel Time: 23.2 ms, GC Workers: 9]
       [GC Worker Start (ms): Min: 14840247.4, Avg: 14840247.6, Max: 
14840247.8, Diff: 0.4]
       [Ext Root Scanning (ms): Min: 3.5, Avg: 4.1, Max: 5.4, Diff: 1.9, 
Sum: 37.2]
       [Update RS (ms): Min: 1.1, Avg: 2.2, Max: 2.8, Diff: 1.7, Sum: 19.8]
          [Processed Buffers: Min: 5, Avg: 9.4, Max: 15, Diff: 10, Sum: 85]
       [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]
       [Object Copy (ms): Min: 15.8, Avg: 16.0, Max: 16.2, Diff: 0.4, 
Sum: 144.2]
       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, 
Sum: 0.8]
       [GC Worker Total (ms): Min: 22.3, Avg: 22.5, Max: 22.7, Diff: 
0.4, Sum: 202.7]
       [GC Worker End (ms): Min: 14840270.1, Avg: 14840270.1, Max: 
14840270.2, Diff: 0.2]
    [Code Root Fixup: 0.0 ms]
    [Clear CT: 0.4 ms]
    [Other: 1.1 ms]
       [Choose CSet: 0.1 ms]
       [Ref Proc: 0.4 ms]
       [Ref Enq: 0.0 ms]
       [Free CSet: 0.3 ms]
    [Eden: 1168.0M(1168.0M)->0.0B(1160.0M) Survivors: 56.0M->64.0M Heap: 
1718.4M(2048.0M)->563.4M(2048.0M)]
  [Times: user=0.21 sys=0.00, real=0.52 secs]
2014-02-20T02:15:43.098+0000: 14840.764: Total time for which 
application threads were stopped: 0.5178390 seconds

Thanks,
Jenny

Thanks,
Jenny

On 2/27/2014 11:51 AM, Kirti Teja Rao wrote:
> There is a follow up question i have. What is the GC phase that is 
> affected due to paging and why is it not showing up in PrintGCDetails? 
> Also, i see this is the time spent after the parallel phase is 
> complete. Any ideas on this?
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140305/b15131c4/attachment.html