java - G1GC 日志中的时间

Question

我读过 G1GC 日志中打印的一些不同时间的描述，但无法真正证明/理解当我在本地生成它们时。例如，以下日志是在我的 Java 11 电脑上生成的。我想知道，第一行的 0.500 毫秒与第二行的 0.01 秒有什么区别？应用程序是否暂停(由于 STW)0.500 毫秒或 10 毫秒(0.01 秒)？我尝试了像 GCeasy 这样的工具，它显示最大暂停时间为 10 毫秒，在 Real = 0.00 的情况下，GCeasy 显示最小暂停时间为 0 毫秒。我想知道，那么0.500ms代表什么样的停顿？

[9.090s][info][gc ] GC(25) Pause Young (Normal) (G1 Evacuation Pause) 77M->2M(128M) 0.500ms

[9.090s][info][gc,cpu ] GC(25) User=0.00s Sys=0.00s Real=0.01s

编辑:gc.logs 与 JMC 中的 GC 暂停时间差异

gc.log 中暂停 0.687 毫秒

根据 JMC 为 1.331 秒

Answer 1

我不确定是否应该将其发布为答案，因为这是我对此日志的理解，但对于评论来说似乎太大了。

如果用 G1GC 的眼光来看，STW 事件的总时间为 0.500ms，但两者都不是 0.500ms 也不是 10ms 如果你以 Shenandoah 为例。当您使用G1GC时，STW事件被视为0.500ms，使用Shenandoah，将导致 0.500ms + 增量；其中此增量是将所有java线程带到安全点(也称为TTSP)所花费的累积时间- 到达安全点的时间)+该安全点需要进行的任何清理工作。也许一张图片会让这件事变得更容易:

   |------|------------------------|---------| 
   | TTPS |   G1 Evacuation Pause  | CleanUp |
   |------|------------------------|---------|

G1GC仅将G1疏散暂停区域视为STW事件。例如，Shenandoah 将整个事件视为 STW 事件(所有 3 个区域)。谁是对的？我将把这件事留给你来决定。

例如，您可以通过 -Xlog:safepoint* 为 G1GC 启用安全点粒度。

你所使用的工具都有自己的“意见”哦，我想如何对待每次产生的日志；但绝对不是10 ms。为什么？正如您已经看到的(正如您在评论中所说)，有时您会在日志中得到类似的内容:

[9.090s][info][gc ] GC(25) Pause Young (Normal) (G1 Evacuation Pause) 77M->2M(128M) 0.500ms

[9.090s][info][gc,cpu ] GC(25) User=0.00s Sys=0.00s Real=**0.00s**

注意Real=0.00s。这是否意味着没有暂停？当然不是，这只意味着没有消耗cpu时间。