Would like to understand why gc time grows

[Yu Zhang]

Barak,

If you can share the entire gc log, we can understand what is going on 
better.  From the snip, user/read ratio is 12.8, and you have 13 gc 
threads. It looks normal.

Thanks,
Jenny

On 2/2/2015 7:39 AM, Barak Yaish wrote:
> Hi,
>
> I'm having my application running on java8 with g1gc enabled. I've 
> enabled gc logs, and I can see that gc time is growing ( at least this 
> is what I think..)
>
> VM flags:
> -Xms6g -Xmx6g 
> -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:G1HeapRegionSize=32M -XX:+PrintAdaptiveSizePolicy 
>
>
> A snippet from the gc log:
>
> {Heap before GC invocations=342 (full 1):
>  garbage-first heap   total 6291456K, used 5257482K 
> [0x0000000640000000, 0x00000007c0000000, 0x00000007c0000000)
>   region size 32768K, 104 young (3407872K), 10 survivors (327680K)
>  Metaspace       used 31200K, capacity 31664K, committed 31872K, 
> reserved 1077248K
>   class space    used 3496K, capacity 3596K, committed 3712K, reserved 
> 1048576K
> 2015-02-02T17:36:48.237+0200: 4067.021: [GC pause (G1 Evacuation 
> Pause) (young) 4067.021: [G1Ergonomics (CSet Construction) start 
> choosing CSet, _pending_cards: 23499, predicted base time: 11.30 ms, 
> remaining time: 188.70 ms, target pause time: 200.00 ms]
>  4067.021: [G1Ergonomics (CSet Construction) add young regions to 
> CSet, eden: 94 regions, survivors: 10 regions, predicted young region 
> time: 159.99 ms]
>  4067.021: [G1Ergonomics (CSet Construction) finish choosing CSet, 
> eden: 94 regions, survivors: 10 regions, old: 0 regions, predicted 
> pause time: 171.29 ms, target pause time: 200.00 ms]
> , 0.2319995 secs]
>    [Parallel Time: 229.0 ms, GC Workers: 13]
>       [GC Worker Start (ms): Min: 4067021.3, Avg: 4067024.1, Max: 
> 4067029.4, Diff: 8.0]
>       [Ext Root Scanning (ms): Min: 0.0, Avg: 0.5, Max: 1.3, Diff: 
> 1.3, Sum: 6.9]
>       [Update RS (ms): Min: 0.6, Avg: 5.3, Max: 7.5, Diff: 6.9, Sum: 69.2]
>          [Processed Buffers: Min: 1, Avg: 10.2, Max: 33, Diff: 32, 
> Sum: 132]
>       [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]
>       [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 
> 0.0, Sum: 0.0]
>       [Object Copy (ms): Min: 219.7, Avg: 219.9, Max: 220.0, Diff: 
> 0.3, Sum: 2858.1]
>       [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 
> 0.9]
>       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, 
> Sum: 1.2]
>       [GC Worker Total (ms): Min: 220.7, Avg: 225.9, Max: 228.8, Diff: 
> 8.0, Sum: 2937.3]
>       [GC Worker End (ms): Min: 4067250.0, Avg: 4067250.1, Max: 
> 4067250.2, Diff: 0.2]
>    [Code Root Fixup: 0.2 ms]
>    [Code Root Migration: 0.0 ms]
>    [Code Root Purge: 0.0 ms]
>    [Clear CT: 1.4 ms]
>    [Other: 1.4 ms]
>       [Choose CSet: 0.0 ms]
>       [Ref Proc: 0.8 ms]
>       [Ref Enq: 0.0 ms]
>       [Redirty Cards: 0.2 ms]
>       [Free CSet: 0.1 ms]
>    [Eden: 3008.0M(3008.0M)->0.0B(2976.0M) Survivors: 320.0M->320.0M 
> Heap: 5134.3M(6144.0M)->2168.1M(6144.0M)]
> Heap after GC invocations=343 (full 1):
>  garbage-first heap   total 6291456K, used 2220163K 
> [0x0000000640000000, 0x00000007c0000000, 0x00000007c0000000)
>   region size 32768K, 10 young (327680K), 10 survivors (327680K)
>  Metaspace       used 31200K, capacity 31664K, committed 31872K, 
> reserved 1077248K
>   class space    used 3496K, capacity 3596K, committed 3712K, reserved 
> 1048576K
> }
>  [Times: user=2.94 sys=0.00, real=0.23 secs]
>
> And the "user" part is keep growing... Can you explain what this 
> actually means? What exact process in the gc in contributing to this? 
> And what can be done in order to minimize this time?
>
> Thanks.
>
>
>
>
> _______________________________________________
> 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/20150202/7fb28c89/attachment.html>