G1GC 日志中的时间答案

【问题标题】：Times in G1GC logsG1GC 日志中的时间
【发布时间】：2020-01-21 00:06:54
【问题描述】：

我已经阅读了 G1GC 日志中打印的一些不同时间的描述，但是当我在本地制作它们时无法真正证明/理解。例如，以下日志是在我的带有 Java 11 的 PC 上生成的。我想知道，第一行的 0.500ms 与第二行的 0.01s 有什么区别？应用程序是暂停（因为 STW）0.500 毫秒还是 10 毫秒（0.01 秒）？我尝试了 GCeasy 之类的工具，它显示最大暂停时间为 10 毫秒，在 Real = 0.00 的情况下，GCeasy 显示最小暂停时间为 0 毫秒。我想知道，那么 0.500ms 代表什么样的停顿呢？

[9.090s][info][gc] GC(25) 暂停 Young (Normal) (G1 疏散暂停) 77M->2M(128M) 0.500ms

[9.090s][信息][gc,cpu] GC(25) 用户=0.00s 系统=0.00s 实际=0.01s

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

gc.log 中的 0.687ms 暂停

根据 JMC 为 1.331 秒

【问题讨论】：

@eugene 你确定吗，总时间是 10 毫秒。因为，我的日志显示了许多情况下暂停时间存在（非零）但 Real 仍然为 0？
我把评论删了，因为我冲进去了，不正确。

标签： java garbage-collection g1gc

【解决方案1】：

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

STW 事件的总时间是0.500ms，如果你用G1GC 的眼睛看，既不是0.500ms，也不是10ms，如果你以Shenandoah 为例。使用G1GC时，STW event被视为0.500ms，使用Shenandoah，会产生0.500ms + delta；其中delta 将是将所有java threads 带到safepoint 所花费的累积时间（也称为TTSP - 到安全点的时间）+ 需要为safepoint 进行任何清理。可能是一张图片会使这更容易：

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

G1GC 将STW Event 视为G1 Evacuation Pause 区域仅。例如，Shenandoah 将整个事物视为 STW 事件（所有 3 个区域）。谁是对的？我将由您决定。

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

您使用的工具有自己的“意见”哦，我猜如何处理日志产生的每次时间；但绝对不是10 ms。为什么？正如您已经看到的（正如您在 cmets 中所说），有时您会在日志中得到类似的内容：

[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 时间。

【讨论】：

如果您看到我的编辑，gc.log 与 JMC 上会显示不同的暂停时间。为什么只是显示集合的暂停时间在不同的工具上会有所不同？
@Abidi 我不知道 JMC 中的数字是多少，我必须阅读文档。但无论如何，这听起来像是你需要问的另一个问题。
@Abidi 好吧，我现在只有时间阅读 JMC 文档，该值是：收集器运行时间的累积持续时间。时间是所有 GC 事件的挂钟时间的总和。您是否碰巧阅读并理解了这一点？
谢谢尤金。我不太明白你的回答，抱歉我的理解不佳。但最后我能够弄清楚，我“认为”它和你说的一样。总 GC 时间为 0.500ms。我不明白的是，它是否以及如何与用户、系统和实时时间相关联。我暂时忽略这个。
@Abidi 没什么好遗憾的，我也在学习这些东西。