G1 GC - pauses much larger than target

[Srinivas Ramakrishna]

Probably some post-GC clean up?... nmethod sweep, monitor list cleanup, and
other housekeeping. There's a trace flag that displays this in more detail:

     bool TraceSafepointCleanupTime                 = false
{product}

Additionally, PrintSafepointStatistics might shed light . Since you have it
already enabled, you could probably look at the data for this particular
pause.
-- ramki


On Thu, Feb 20, 2014 at 1:24 AM, Kirti Teja Rao <kirtiteja at gmail.com> wrote:

> 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
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140220/d3050ce2/attachment.html