zgc pause time includes concurrent time

[linking12]

formula：rate(jvm_gc_pause_seconds_sum{application="$application", instance="$instance"}[1m])/rate(jvm_gc_pause_seconds_count{application="$application", instance="$instance"}[1m])

question：
The STW time of zgc is less 10ms, but why jvm_gc_pause_time is 822ms? can not understand this phenomenon

[linking12]

I think isConcurrentPhase is wrong for zgc

private boolean isConcurrentPhase(GarbageCollectionNotificationInfo info) {
    // So far the only indicator known is that the cause will be reported as "No GC"
    // when using CMS.
    //
    // For ZGC, the allocation stall seems to indicate that some thread or threads are
    // blocked trying to allocate. Even though it is not a true STW pause, counting it
    // as such seems to be less confusing.
    return "No GC".equals(info.getGcCause())            // CMS
        || "Shenandoah Cycles".equals(info.getGcName()) // Shenandoah
        || ("ZGC".equals(info.getGcName()) && !"Allocation Stall".equals(info.getGcCause()));
  }

https://github.com/Netflix/spectator/blob/3d428b3c69c80f7067772e27ce0032cf11d8ec9c/spectator-ext-gc/src/main/java/com/netflix/spectator/gc/GcLogger.java
Netflix is right?

[shakuzen]

Thank you for the report. Things do seem probably out of sorts. I'd like to check on the ZGC devs mailing list what the correct way is to separate out concurrent and pause time from gc notifications.

[shakuzen]

I also just came across JDK-8255289. The comments seem to indicate it's no longer possible in the latest implementations to distinguish pause time from concurrent time using the gc notifications for ZGC. This is unfortunate, especially since there doesn't seem to be an alternative available currently either.

[linking12]

I also just came across JDK-8255289. The comments seem to indicate it's no longer possible in the latest implementations to distinguish pause time from concurrent time using the gc notifications for ZGC. This is unfortunate, especially since there doesn't seem to be an alternative available currently either.

Make a suggestion，For ZGC, the allocation stall seems to indicate that some thread or threads are blocked trying to allocate. Even though it is not a true STW pause, counting it as such seems to be less confusing.

[shakuzen]

I think that comment from the Spectator code is based on the behavior before the change mentioned in a comment on JDK-8255289:

as part of JDK-8240679, the GarbageCollectorMXBean was changed to report data covering the complete GC cycle, instead of individual GC pauses. A complete GC cycle in ZGC includes three (very short) pauses plus all concurrent phases. So, in the examples above you are comparing individual GC pauses (JDK 14) with the time for a complete concurrent GC cycle (JDK 15).

If you run an application with gc logging on you can see the pause time and concurrent time separately. The gc notification is including the concurrent time for ZGC cycles, even when the cause Allocation Stall isn't involved. In the below instance, the cause is Metadata GC Threshold. I started up a Spring Boot application and can see the following GC log with the following metrics.

[2.406s][info][gc,phases] GC(1) Pause Mark Start 0.507ms
[2.458s][info][gc,phases] GC(1) Concurrent Mark 51.175ms
[2.458s][info][gc,phases] GC(1) Pause Mark End 0.125ms
[2.462s][info][gc,phases] GC(1) Concurrent Process Non-Strong References 3.647ms
[2.462s][info][gc,phases] GC(1) Concurrent Reset Relocation Set 0.549ms
[2.468s][info][gc,phases] GC(1) Concurrent Select Relocation Set 5.721ms
[2.468s][info][gc,phases] GC(1) Pause Relocate Start 0.213ms
[2.478s][info][gc,phases] GC(1) Concurrent Relocate 9.883ms
[2.478s][info][gc       ] GC(1) Garbage Collection (Metadata GC Threshold) 176M(2%)->84M(1%)

jvm_gc_pause_seconds_count{action="end of major GC",cause="Metadata GC Threshold",} 1.0
jvm_gc_pause_seconds_sum{action="end of major GC",cause="Metadata GC Threshold",} 0.073

Edit: To be clear, our metric is showing 73 milliseconds of pause time, but you can see from the GC logs that the 3 pauses add up to less than 1 millisecond - the rest is concurrent phases.

Given how wrong the pause time metric is for ZGC, I'm strongly considering removing support for ZGC unless we can find a way to get the information.

Edit: I should note that I'm running the above code with Java 15.0.1.

[linking12]

I think that comment from the Spectator code is based on the behavior before the change mentioned in a comment on JDK-8255289:

as part of JDK-8240679, the GarbageCollectorMXBean was changed to report data covering the complete GC cycle, instead of individual GC pauses. A complete GC cycle in ZGC includes three (very short) pauses plus all concurrent phases. So, in the examples above you are comparing individual GC pauses (JDK 14) with the time for a complete concurrent GC cycle (JDK 15).

If you run an application with gc logging on you can see the pause time and concurrent time separately. The gc notification is including the concurrent time for ZGC cycles, even when the cause Allocation Stall isn't involved. In the below instance, the cause is Metadata GC Threshold. I started up a Spring Boot application and can see the following GC log with the following metrics.

[2.406s][info][gc,phases] GC(1) Pause Mark Start 0.507ms
[2.458s][info][gc,phases] GC(1) Concurrent Mark 51.175ms
[2.458s][info][gc,phases] GC(1) Pause Mark End 0.125ms
[2.462s][info][gc,phases] GC(1) Concurrent Process Non-Strong References 3.647ms
[2.462s][info][gc,phases] GC(1) Concurrent Reset Relocation Set 0.549ms
[2.468s][info][gc,phases] GC(1) Concurrent Select Relocation Set 5.721ms
[2.468s][info][gc,phases] GC(1) Pause Relocate Start 0.213ms
[2.478s][info][gc,phases] GC(1) Concurrent Relocate 9.883ms
[2.478s][info][gc       ] GC(1) Garbage Collection (Metadata GC Threshold) 176M(2%)->84M(1%)

jvm_gc_pause_seconds_count{action="end of major GC",cause="Metadata GC Threshold",} 1.0
jvm_gc_pause_seconds_sum{action="end of major GC",cause="Metadata GC Threshold",} 0.073

Edit: To be clear, our metric is showing 73 milliseconds of pause time, but you can see from the GC logs that the 3 pauses add up to less than 1 millisecond - the rest is concurrent phases.

Given how wrong the pause time metric is for ZGC, I'm strongly considering removing support for ZGC unless we can find a way to get the information.

Edit: I should note that I'm running the above code with Java 15.0.1.

I don't think so for removing support ZGC, JVM pause time is very important for the application's health;
Can we use GarbageCollectorMXBean like prometheus exporter agent?

public interface GarbageCollectorMXBean extends MemoryManagerMXBean {
    /**
     * Returns the total number of collections that have occurred.
     * This method returns <tt>-1</tt> if the collection count is undefined for
     * this collector.
     *
     * @return the total number of collections that have occurred.
     */
    public long getCollectionCount();

    /**
     * Returns the approximate accumulated collection elapsed time
     * in milliseconds.  This method returns <tt>-1</tt> if the collection
     * elapsed time is undefined for this collector.
     * <p>
     * The Java virtual machine implementation may use a high resolution
     * timer to measure the elapsed time.  This method may return the
     * same value even if the collection count has been incremented
     * if the collection elapsed time is very short.
     *
     * @return the approximate accumulated collection elapsed time
     * in milliseconds.
     */
    public long getCollectionTime();


}

Also I think the allocation stall is very import for a java application when it apply memory.

[shakuzen]

JVM pause time is very important for the application's health

I agree. The issue is we cannot get that information.

Can we use GarbageCollectorMXBean like prometheus exporter agent?

No because ZGC is also reporting there the total collection time, including pauses and concurrent phases.

[0.820s][info][gc,phases] GC(0) Pause Mark Start 0.503ms
[0.826s][info][gc,phases] GC(0) Concurrent Mark 5.658ms
[0.826s][info][gc,phases] GC(0) Pause Mark End 0.037ms
[0.827s][info][gc,phases] GC(0) Concurrent Process Non-Strong References 0.596ms
[0.827s][info][gc,phases] GC(0) Concurrent Reset Relocation Set 0.000ms
[0.840s][info][gc,phases] GC(0) Concurrent Select Relocation Set 13.007ms
[0.840s][info][gc,phases] GC(0) Pause Relocate Start 0.188ms
[0.844s][info][gc,phases] GC(0) Concurrent Relocate 3.514ms
[0.844s][info][gc       ] GC(0) Garbage Collection (System.gc()) 62M(1%)->50M(1%)
MeterId{name='jvm.gc.pause', tags=[tag(action=end of major GC),tag(cause=System.gc())]} [Measurement{statistic='COUNT', value=1.0}, Measurement{statistic='TOTAL_TIME', value=0.024}, Measurement{statistic='MAX', value=0.024}]
ZGC (1) 24ms

The last line is what is reported from the GarbageCollectorMXBean for ZGC. You can see from the gc logs that 24ms is the total collection time, including concurrent phases. I'm not seeing any way to get just the pause time.

[maciek-codes]

It appears that in JDK 17 the GarbageCollectorMXBean added information about collection time and pause time:
https://bugs.openjdk.java.net/browse/JDK-8265136
Commit 79798c65

[shakuzen]

@macqm Thanks for sharing. That's good to know. I'll have to take another look at our gc metrics with zgc in 17.