<div dir="ltr"><div>Hi,</div><div><br></div><div>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.</div>
<div>Can anyone please help in identifying where this time is spent or how to bring it down? </div><div><br></div><div>Below is the log for one such occurrence and also the JVM parameters for this run - </div><div><br></div>
<div>My observations - </div><div>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.</div><div>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.</div>
<div><br></div><div>I can add more logs if required. I can also run it in same env with different parameters if there are suggestions.</div><br><div><div>2014-02-20T02:15:42.580+0000: 14840.246: Application time: 8.5619840 seconds</div>
<div>2014-02-20T02:15:42.581+0000: 14840.247: [GC pause (young)</div><div>Desired survivor size 83886080 bytes, new threshold 15 (max 15)</div><div>- age 1: 2511184 bytes, 2511184 total</div><div>- age 2: 1672024 bytes, 4183208 total</div>
<div>- age 3: 1733824 bytes, 5917032 total</div><div>- age 4: 1663920 bytes, 7580952 total</div><div>- age 5: 1719944 bytes, 9300896 total</div><div>- age 6: 1641904 bytes, 10942800 total</div>
<div>- age 7: 1796976 bytes, 12739776 total</div><div>- age 8: 1706344 bytes, 14446120 total</div><div>- age 9: 1722920 bytes, 16169040 total</div><div>- age 10: 1729176 bytes, 17898216 total</div>
<div>- age 11: 1500056 bytes, 19398272 total</div><div>- age 12: 1486520 bytes, 20884792 total</div><div>- age 13: 1618272 bytes, 22503064 total</div><div>- age 14: 1492840 bytes, 23995904 total</div>
<div>- age 15: 1486920 bytes, 25482824 total</div><div> 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]</div>
<div> 14840.247: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 146 regions, survivors: 7 regions, predicted young region time: 8.76 ms]</div><div> 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]</div>
<div>, 0.0247660 secs]</div><div> [Parallel Time: 23.2 ms, GC Workers: 9]</div><div> [GC Worker Start (ms): Min: 14840247.4, Avg: 14840247.6, Max: 14840247.8, Diff: 0.4]</div><div> [Ext Root Scanning (ms): Min: 3.5, Avg: 4.1, Max: 5.4, Diff: 1.9, Sum: 37.2]</div>
<div> [Update RS (ms): Min: 1.1, Avg: 2.2, Max: 2.8, Diff: 1.7, Sum: 19.8]</div><div> [Processed Buffers: Min: 5, Avg: 9.4, Max: 15, Diff: 10, Sum: 85]</div><div> [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]</div>
<div> [Object Copy (ms): Min: 15.8, Avg: 16.0, Max: 16.2, Diff: 0.4, Sum: 144.2]</div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]</div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]</div>
<div> [GC Worker Total (ms): Min: 22.3, Avg: 22.5, Max: 22.7, Diff: 0.4, Sum: 202.7]</div><div> [GC Worker End (ms): Min: 14840270.1, Avg: 14840270.1, Max: 14840270.2, Diff: 0.2]</div><div> [Code Root Fixup: 0.0 ms]</div>
<div> [Clear CT: 0.4 ms]</div><div> [Other: 1.1 ms]</div><div> [Choose CSet: 0.1 ms]</div><div> [Ref Proc: 0.4 ms]</div><div> [Ref Enq: 0.0 ms]</div><div> [Free CSet: 0.3 ms]</div><div> [Eden: 1168.0M(1168.0M)->0.0B(1160.0M) Survivors: 56.0M->64.0M Heap: 1718.4M(2048.0M)->563.4M(2048.0M)]</div>
<div> [Times: user=0.21 sys=0.00, real=0.52 secs]</div><div>2014-02-20T02:15:43.098+0000: 14840.764: Total time for which application threads were stopped: 0.5178390 seconds</div></div><div><br></div><div>JVM parameters - </div>
<div><br></div><div>-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<br>
</div></div>