Measuring Stop-the-World(STW) Pauses

[Alex Elent]

Thanks again gentlemen.

On Wed, May 22, 2019 at 12:53 PM Roman Kennke <rkennke at redhat.com> wrote:

> Hi Alex,
>
> > Just wanted to validate that this is also a STW pause:
> >
> > 2019-05-22T19:45:37.182+0000: 66424.311: [Pause Init Mark (process
> > weakrefs), 2.344 ms]
>
> Yes, it is. :-)
>
> Roman
>
>
>
> > Thanks,
> >
> > On Tue, May 21, 2019 at 2:47 PM Alex Elent <alex at scalyr.com> wrote:
> >
> >> 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
> >>>
> >>>
>
>