Measuring Stop-the-World(STW) Pauses

[Alex Elent]

Hello,

We are evaluating Shenandoah GC for our application. In order to evaluate
we'd like to measure the STW pauses. Would anyone be able to assist in
identifying which log lines we should be evaluating? We are using JDK8
(also in progress of upgrading to JDK11). Should we be looking at entries
that contain the "Pause" keyword? Does that indicate a STW pause? Is there
anything else we should be counting towards the STW pauses?

Thank you so much for your help!

A snippet of our logs:
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]