Measuring Stop-the-World(STW) Pauses

[Alex Elent]

That's absolutely perfect, thanks!

On Tue, May 21, 2019 at 2:31 PM Aleksey Shipilev <shade at redhat.com> wrote:

> 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
>
>