G1 GC - pauses much larger than target
YU ZHANG
yu.zhang at oracle.com
Thu Feb 20 12:42:03 PST 2014
Kirti,
If real time is longer than user time, it means the gc threads were
waiting for cpu. How is your cpu utilization?
Thanks,
Jenny
On 2/20/2014 12:12 PM, Kirti Teja Rao wrote:
> 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 <mailto: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 <mailto: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
> <mailto:hotspot-gc-use at openjdk.java.net>
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
>
>
>
> _______________________________________________
> 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/71cad4a7/attachment-0001.html
More information about the hotspot-gc-use
mailing list