G1GC日志中的时间

Question

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

9.090sgc GC(25)暂停年轻(正常) (G1疏散暂停)77m->2m(128米)0.500 GC

9.090sgc，cpu GC(25) User=0.00s Sys=0.00s Real=0.01s

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

gc.log中的0.687ms暂停

​

根据JMC的说法是1.331秒

​

Answer 1

我不确定我是否应该把这作为一个答案，因为这是我对这个日志的理解，但它太大了，似乎无法发表评论。

如果您用STW的眼睛看，那么0.500ms事件的总时间是0.500ms，以Shenandoah为例，它既不是0.500ms，也不是10ms。当您使用G1GC时，STW event被视为0.500ms，使用Shenandoah将导致0.500ms + delta；在这里，这个delta将是将所有java threads带到safepoint (也称为TTSP - time to safe )的累积时间，+该safepoint所需的清理时间。也许是一幅画会使这件事变得更容易：

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

G1GC只将G1 Evacuation Pause区域作为STW Event处理。例如，Shenandoah将整个事件视为STW事件(所有三个区域)。谁是对的？我将由你来决定。

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

您使用的工具都有自己的“意见”--哦，如何处理日志生成的每一次，我猜，但这绝对不是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时间。