Safepoint+stats 日志，输出 JDK12 中没有 vmop 操作

2022-01-16 00:00:00 jvm java zgc

我在 JDK12 上使用 -Xlog:safepoint+stats=debug:file=safepoint.log vm 参数运行应用程序来记录安全点操作并使用 ZGC 运行.我有问题理解日志输出:

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

我理解第一行告诉 ZOperation 花费了 1 毫秒，并且 7 个线程促成了阻塞.

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

第二行没看懂，什么是"None" vmop操作?看起来该操作的持续时间为 0.它真的是 0 还是 0 因为它花费了不到 1 毫秒?如果是，可以设置更高粒度的时间记录，看看花了多少纳秒?还是微秒?

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?

我每秒记录许多这种无"操作.我想知道 JVM 在暂停期间在做什么.我每 10 秒跟踪一次 ZGC 时间和 SafePoint 时间，聚合的安全点时间是聚合的 gc 暂停时间的 5 倍.我想以某种方式减少我的应用程序的安全点时间.

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.

推荐答案

这是一个没有虚拟机操作的安全点.其目的是执行定期清理任务，例如放空空闲监视器或清除内联缓存缓冲区，这些任务只有在没有 Java 线程运行时才能安全地完成.

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.

如果有清理任务要做，强制安全点每 GuaranteedSafepointInterval 毫秒发生一次.默认值为 1000.请注意，在您的情况下，无操作安全点恰好在前一个安全点之后 1 秒发生.

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.

间隔可以调整

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

为避免混淆，在 JDK 13 中，此类无操作安全点获得了 Cleanup 操作名称.

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

相关文章