Rare very big pause

[Aleksey Shipilev]

On 12/19/2017 06:43 PM, Kirill A. Korinsky wrote:
> Well, it helps decrease pauses, but it is still about 150-200 ms.
> 
> For example:
> 
> Concurrent marking triggered. Free: 1718M, Free Threshold: 1720M; Allocated: 1718M, Alloc Threshold: 0M
> 2017-12-19T16:59:02.785+0000: 3055.494: [Pause Init Mark, 2.553 ms]
> 2017-12-19T16:59:02.788+0000: 3055.496: [Concurrent marking 4418M->4723M(6144M), 916.628 ms]
> 2017-12-19T16:59:03.710+0000: 3056.419: [Pause Final MarkTotal Garbage: 3555M
> Immediate Garbage: 1374M, 688 regions (41% of total)
> Garbage to be collected: 1849M (52% of total), 965 regions
> Live objects to be evacuated: 80M
> Live/garbage ratio in collected regions: 4%
>  4723M->3351M(6144M), 175.951 ms]
> 2017-12-19T16:59:03.886+0000: 3056.595: [Concurrent evacuation 3352M->3453M(6144M), 71.376 ms]
> 2017-12-19T16:59:03.959+0000: 3056.667: [Pause Init Update Refs, 0.099 ms]
> 2017-12-19T16:59:03.959+0000: 3056.667: [Concurrent update references  3453M->3489M(6144M), 578.340 ms]
> 2017-12-19T16:59:04.538+0000: 3057.246: [Pause Final Update Refs 3489M->1560M(6144M), 2.241 ms]
> 2017-12-19T16:59:04.540+0000: 3057.249: [Concurrent reset bitmaps 1560M->1560M(6144M), 3.516 ms]
> Capacity: 6144M, Peak Occupancy: 4723M, Lowest Free: 1420M, Free Threshold: 1228M
> Adjusting free threshold to: 25% (1536M)

This one looks like legit non-degraded Final Mark pause. Seeing 175ms for that pause seems odd,
unless you are running fastdebug builds (in which case you will spend some time zapping the memory).
With -verbose:gc, there would be the GC stats table after JVM exits, which will dissect that pause
much better.

-Aleksey