Measuring Stop-the-World(STW) Pauses

[Alex Elent]

Hi Aleksey,

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]

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