G1 GC - pauses much larger than target
Kirti Teja Rao
kirtiteja at gmail.com
Thu Feb 20 12:12:47 PST 2014
Hi,
I re-ran the test with TraceSafepointCleanupTime enabled. I did not find
anything out of ordinary.
Safepoint cleanup is showing only sub-milliseconds. Below are the logs for
one such occurrence.
I can also run the app with -XX:+PrintHeapAtGC -XX:+PrintHeapAtGCExtended
if it helps. I did ran it once earlier could not find anything out of
ordinary.
safepoint trace -
1711.616: [deflating idle monitors, 0.0000510 secs]
1711.616: [updating inline caches, 0.0000010 secs]
1711.616: [compilation policy safepoint handler, 0.0001860 secs]
1711.616: [sweeping nmethods, 0.0000040 secs]
vmop [threads: total initially_running
wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
1711.616: G1IncCollectionPause [ 94 0
0 ] [ 0 0 0 0 235 ] 0
gc log -
2014-02-20T19:49:45.588+0000: 1711.616: Application time: 4.5889130 seconds
2014-02-20T19:49:45.588+0000: 1711.616: [GC pause (young)
Desired survivor size 83886080 bytes, new threshold 15 (max 15)
- age 1: 1428296 bytes, 1428296 total
- age 2: 918104 bytes, 2346400 total
- age 3: 1126320 bytes, 3472720 total
- age 4: 838696 bytes, 4311416 total
- age 5: 975512 bytes, 5286928 total
- age 6: 813872 bytes, 6100800 total
- age 7: 975504 bytes, 7076304 total
- age 8: 801600 bytes, 7877904 total
- age 9: 966256 bytes, 8844160 total
- age 10: 801536 bytes, 9645696 total
- age 11: 964048 bytes, 10609744 total
- age 12: 859568 bytes, 11469312 total
- age 13: 931344 bytes, 12400656 total
- age 14: 921024 bytes, 13321680 total
- age 15: 891616 bytes, 14213296 total
1711.616: [G1Ergonomics (CSet Construction) start choosing CSet,
_pending_cards: 9059, predicted base time: 6.60 ms, remaining time: 18.40
ms, target pause time: 25.00 ms]
1711.616: [G1Ergonomics (CSet Construction) add young regions to CSet,
eden: 150 regions, survivors: 3 regions, predicted young region time: 5.94
ms]
1711.616: [G1Ergonomics (CSet Construction) finish choosing CSet, eden:
150 regions, survivors: 3 regions, old: 0 regions, predicted pause time:
12.54 ms, target pause time: 25.00 ms]
, 0.0180830 secs]
[Parallel Time: 17.0 ms, GC Workers: 9]
[GC Worker Start (ms): Min: 1711616.5, Avg: 1711616.6, Max:
1711616.8, Diff: 0.3]
[Ext Root Scanning (ms): Min: 3.5, Avg: 4.8, Max: 6.0, Diff: 2.4,
Sum: 43.1]
[Update RS (ms): Min: 0.7, Avg: 1.7, Max: 2.7, Diff: 2.0, Sum: 15.2]
[Processed Buffers: Min: 4, Avg: 8.1, Max: 17, Diff: 13, Sum: 73]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
[Object Copy (ms): Min: 9.7, Avg: 9.8, Max: 10.0, Diff: 0.3, Sum:
88.1]
[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.3, Diff: 0.3, Sum:
1.1]
[GC Worker Total (ms): Min: 16.3, Avg: 16.5, Max: 16.6, Diff: 0.4,
Sum: 148.4]
[GC Worker End (ms): Min: 1711633.0, Avg: 1711633.1, Max: 1711633.3,
Diff: 0.3]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 0.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 1200.0M(1200.0M)->0.0B(1200.0M) Survivors: 24.0M->24.0M Heap:
1566.3M(2048.0M)->370.6M(2048.0M)]
[Times: user=0.15 sys=0.00, real=0.24 secs]
2014-02-20T19:49:45.824+0000: 1711.852: Total time for which application
threads were stopped: 0.2361710 seconds
On Thu, Feb 20, 2014 at 2:04 AM, Srinivas Ramakrishna <ysr1729 at gmail.com>wrote:
> 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/295f0bbe/attachment.html
More information about the hotspot-gc-use
mailing list