Would like to understand why gc time grows

Mon Feb 2 19:53:12 UTC 2015

Thanks for the quick response :-)

My app supposed to serve as a simple web server, responding to requests in
less than 30ms, no long lived objects... Doesn't the increasing value of
"user" time indicates STW pauses? And which tool you use to parse the log?
Most tools I was trying to use are failing to parse correctly g1 logs..

On Mon, Feb 2, 2015 at 9:40 PM, Yu Zhang <yu.zhang at oracle.com> wrote:

>  Barak,
>
> Thanks for the gc log.
>
> The stop the world pause in your log includes, young, mixed, remark and
> clean up phases.
> For details on how to under stand gc logs, please see
> https://blogs.oracle.com/g1gc/date/20140801
> https://blogs.oracle.com/g1gc/date/20140807
>
> Here is a chart of the gc pauses from your log. Can not conclude gc pause
> is getting longer.
> The default MaxGCPauseMillis is 200 (ms), does it work for you? Or you
> need lower pause time?
>
>  Thanks,
> Jenny
>
> On 2/2/2015 10:58 AM, Barak Yaish wrote:
>
> Sure, upload the file to
> https://www.dropbox.com/sh/kinl4zo8apg6kh2/AADlh9b-X_Zk6L_tgPL_lyyma?dl=0
>
>  Can you explain which messages indicates the time the app was paused due
> to gc?
>
>  Thanks!
>
> On Mon, Feb 2, 2015 at 6:23 PM, Yu Zhang <yu.zhang at oracle.com> wrote:
>
>>  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 listhotspot-gc-use at openjdk.java.nethttp://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/d1fae2d2/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: hihgjffh.png
Type: image/png
Size: 15756 bytes
Desc: not available
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150202/d1fae2d2/hihgjffh.png>