Measuring Stop-the-World(STW) Pauses

[Aleksey Shipilev]

On 5/21/19 11:14 PM, Alex Elent wrote:
> Should we be looking at entries that contain the "Pause" keyword?
Yes. Everything with "Pause" is global STW pause. This should correlate to MXBean "Shenandoah
Pauses" (if you are running external monitoring service), safepoint logging
(-XX:+PrintSafepointStatistics), etc. With -verbose:gc, you should also have the summary table at
the end of the run, which would dissect the pauses more thoroughly.

In your log below, there is 2.032ms Final Mark, 0.061ms Init Update Refs, 1.142ms Final Update Refs
pauses (there should also be Init Mark in the beginning). There are normally four pauses per GC
cycle, sometimes less if cycle shortcuts.

> 2019-05-21T21:11:34.249+0000: 2026.775: [Pause Final Mark, 2.032 ms]
> 2019-05-21T21:11:34.249+0000: 2026.775: [Concurrent cleanup, start]
> 2019-05-21T21:11:34.250+0000: 2026.776: [Concurrent cleanup
> 8645M->2324M(10G), 1.147 ms]
> Free: 7358M (1853 regions), Max regular: 4096K, Max humongous: 962560K,
> External frag: 88%, Internal frag: 0%
> Evacuation Reserve: 509M (128 regions), Max regular: 4096K
> 2019-05-21T21:11:34.250+0000: 2026.776: [Concurrent evacuation, start]
>     Using 4 of 4 workers for concurrent evacuation
> 2019-05-21T21:11:34.256+0000: 2026.782: [Concurrent evacuation
> 2324M->2329M(10G), 5.720 ms]
> 2019-05-21T21:11:34.256+0000: 2026.782: [Pause Init Update Refs, start]
>     Pacer for Update Refs. Used: 2329M, Free: 7358M, Non-Taxable: 735M,
> Alloc Tax Rate: 1.1x
> 2019-05-21T21:11:34.256+0000: 2026.782: [Pause Init Update Refs, 0.061 ms]
> 2019-05-21T21:11:34.256+0000: 2026.782: [Concurrent update references,
> start]
>     Using 4 of 4 workers for concurrent reference update
> 2019-05-21T21:11:34.279+0000: 2026.805: [Concurrent update references
> 2329M->2330M(10G), 23.211 ms]
> 2019-05-21T21:11:34.280+0000: 2026.806: [Pause Final Update Refs, start]
>     Using 4 of 4 workers for final reference update
> 2019-05-21T21:11:34.281+0000: 2026.807: [Pause Final Update Refs, 1.142 ms]
> 2019-05-21T21:11:34.281+0000: 2026.807: [Concurrent cleanup, start]
> 2019-05-21T21:11:34.281+0000: 2026.807: [Concurrent cleanup
> 2330M->390M(10G), 0.455 ms]
> Free: 9321M (2345 regions), Max regular: 4096K, Max humongous: 4575232K,
> External frag: 53%, Internal frag: 0%
> Evacuation Reserve: 512M (128 regions), Max regular: 4096K
> Pacer for Idle. Initial: 204M, Alloc Tax Rate: 1.0x
> Trigger: Free (1023M) is below minimum threshold (1023M)
> Free: 1023M (270 regions), Max regular: 4096K, Max humongous: 978944K,
> External frag: 7%, Internal frag: 5%
> Evacuation Reserve: 512M (128 regions), Max regular: 4096K
> 2019-05-21T21:12:15.373+0000: 2067.899: [Concurrent reset, start]
>     Using 4 of 4 workers for concurrent reset
> 2019-05-21T21:12:15.377+0000: 2067.903: [Concurrent reset
> 8640M->8643M(10G), 4.835 ms]
> 2019-05-21T21:12:15.378+0000: 2067.904: [Pause Init Mark (process
> weakrefs), start]
>     Using 4 of 4 workers for init marking
>     Pacer for Mark. Expected Live: 295M, Free: 1020M, Non-Taxable: 102M,
> Alloc Tax Rate: 1.1x
> 2019-05-21T21:12:15.380+0000: 2067.906: [Pause Init Mark (process
> weakrefs), 2.050 ms]


-- 
Thanks,
-Aleksey