Measuring STW Pauses

[Alex Elent]

Hi Per,

Thanks for reaching out so quickly. I've subscribed to zgc-dev as well.

Complete transparency, I'm not that familiar with Java GC. Although that
was probably made obvious from my previous question.

Let me give you some context. I'd like to migrate to ZGC from Parallel GC.
When using Parallel GC the GC log has clear entries for "Pause" events
which I understand to be stop the world pauses. For example Pause Full
Ergonomics or Pause Full System.gc ().

What gc log timings would one need to parse in ZGC logs in order to measure
total stop the world pauses?

Thanks again,

On Tue, Nov 20, 2018, 11:20 PM Per Liden <per.liden at oracle.com wrote:

> Hi Alex,
>
> (note that you need to be subscribed to zgc-dev at openjdk.java.net to be
> able to send messages to the list, else a moderator has to approve each
> message).
>
> On 11/21/18 12:52 AM, Alex Elent wrote:
> > Hello,
> >
> > I read through JEP 333 and it looks incredibly promising. My question is,
> > how does one measure the STW pauses in ZGC?
> >
> > I read through the mailing list archives and understand there are 3
> pauses:
> > Pause Mark Start
> > Pause Mark End
> > Pause Relocate Start
> >
> > Using the below snippet of gc log:
> > [2018-11-20T23:34:46.180+0000][5135ms] GC(1) *Pause Mark Start 4.975ms*
> > [2018-11-20T23:34:46.301+0000][5256ms] GC(1) Concurrent Mark 120.118ms
> > [2018-11-20T23:34:46.301+0000][5256ms] GC(1) *Pause Mark End 0.684ms*
> > [2018-11-20T23:34:46.304+0000][5259ms] GC(1) Concurrent Process
> Non-Strong
> > References 2.308ms
> > [2018-11-20T23:34:46.304+0000][5259ms] GC(1) Concurrent Reset Relocation
> > Set 0.008ms
> > [2018-11-20T23:34:46.304+0000][5259ms] GC(1) Concurrent Destroy Detached
> > Pages 0.001ms
> > [2018-11-20T23:34:46.305+0000][5260ms] GC(1) Concurrent Select Relocation
> > Set 1.072ms
> > [2018-11-20T23:34:46.306+0000][5261ms] GC(1) Concurrent Prepare
> Relocation
> > Set 1.078ms
> > [2018-11-20T23:34:46.310+0000][5265ms] GC(1) *Pause Relocate Start
> 3.764ms*
> >
> > Does that mean the STW pause for that cycle was 4.975 + 0.684 + 3.764
> > (9.423)?
>
> No, the goal of 10ms max pause time refers to each individual pause, not
> the sum of them. The three pauses in ZGC are typically spaced out in
> time (by heavy operations such as concurrent marking and relocation), so
> treating them as one single pause would not make sense. Note that we
> also track MMU (Minimum Mutator Utilization, also printed in the GC
> log), which reflects pause times and how they are spaced out in time.
>
> cheers,
> Per
>
> >
> > Thanks in advance,
> >
>