Measuring STW Pauses

[Per Liden]

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