Safepoint+stats log with None vmop operation in output JDK12

Question

I am running application on the JDK12 with the -Xlog:safepoint+stats=debug:file=safepoint.log vm parameter to log the safepoint actions and running with ZGC. I have the problem to understand the log output:

[1408.417s][debug][safepoint,stats]           vmop                            [ threads:    total initially_running wait_to_block ][ time:    spin   block    sync cleanup    vmop ] page_trap_count
[1412.164s][debug][safepoint,stats] 1412.162: ZOperation                    [               376                 0             7 ][             0       0       0       0       1 ]               7
[1413.164s][debug][safepoint,stats] 1413.164: None                          [               376                 0             0 ][             0       0       0       0       0 ]               0
[1414.165s][debug][safepoint,stats] 1414.164: None                          [               376                 0             1 ][             0       0       0       0       0 ]               1

I understand the first line that tells that ZOperation took 1 millis, and 7 threads contributed in blocking.

I don't understand the second line, what is the "None" vmop operation? It looks like the duration of that operation is 0. It is really 0 or it is 0 because it took less than 1 millisecond? If yes it is possible to set higher granularity of time logging, to see how many nanoseconds it took ? or microseconds?

I have many of this "None" operation logged per seconds. I would like to know what the JVM is doing during that pause. I track the ZGC time and SafePoint time every 10 seconds, and the aggregated safepoint time is 5 times higher than aggregated gc pause time. I would like to somehow decrease that safepoint time for my application.

Answer 1

This is a safepoint with no VM operation. Its purpose is to perform periodic cleanup tasks like deflating idle monitors or purging inline cache buffer, which can be safely done only when no Java threads are running.

If there are cleanup tasks to do, a mandatory safepoint happens every GuaranteedSafepointInterval milliseconds. The default value is 1000. Note that in your case no-op safepoint happens exactly 1 second after the previous safepoint.

The interval can be tuned with

-XX:+UnlockDiagnosticVMOptions -XX:GuaranteedSafepointInterval=<ms>

To avoid confusion, in JDK 13 such no-op safepoints got Cleanup operation name.