G1 GC - pauses much larger than target

[Kirti Teja Rao]

Hi,

I am trying out G1 collector for our application. Our application runs with
2GB heap and we expect relatively low latency. The pause time target is set
to 25ms. There are much bigger pauses (and unexplained) in order of few
100s of ms. This is not a rare occurence and i can see this 15-20 times in
6-7 hours runs. We use deterministic GC in jrockit for 1.6 and want to
upgrade to 1.7 or even 1.8 after the next months release. Explaining and
tuning these unexplained large pauses is critical for us to upgrade.
Can anyone please help in identifying where this time is spent or how to
bring it down?

Below is the log for one such occurrence and also the JVM parameters for
this run -

My observations -
1) real time is much larger than the user time. This server has 2
processors with 8 cores each and hyper-threading. So, for most of time the
progress is blocked.
2) Start time is 14840.246, end time for worker is 14840270.2 and end time
for pause is 14840.764. So, the time is spent after the parallel phase is
completed and before the pause finishes.

I can add more logs if required. I can also run it in same env with
different parameters if there are suggestions.

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

JVM parameters -

-server -Xmx2g -Xms2g -XX:PermSize=128m -XX:MaxPermSize=128m
-XX:+UseLargePages -XX:LargePageSizeInBytes=2m -XX:+UseG1GC
-XX:MaxGCPauseMillis=25 -XX:ParallelGCThreads=9 -XX:ConcGCThreads=4
-XX:G1HeapRegionSize=8M -XX:+PrintTLAB -XX:+AggressiveOpts
-XX:+PrintFlagsFinal -Xloggc:/integral/logs/gc.log -verbose:gc
-XX:+PrintTenuringDistribution -XX:+PrintGCDateStamps
 -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCDetails
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1
-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=3026
-Dcom.sun.management.jmxremote.local.only=false
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140220/202afb4a/attachment.html