G1GC日志中的时间 [英] Times in G1GC logs
问题描述
我已经阅读了G1GC日志中打印的关于不同时间的一些描述，但是当我在本地生产它们时并不能真正证明/理解.例如，以下日志是在装有Java 11的PC上生成的.我想知道，第一行0.500ms与第二行0.01s有什么区别?是由于STW暂停了应用程序0.500毫秒还是10毫秒(0.01 s)?我尝试了诸如GCeasy之类的工具，它显示的最大暂停时间为10ms，在Real = 0.00的情况下，GCeasy显示的最小暂停时间为0ms.我想知道，0.500ms代表什么类型的暂停?
I've read a few descriptions of different times printed in G1GC logs but couldn't really prove/understand when I produced them locally. For example, following log was produced on my PC with Java 11. I wanted to know, what's the difference between 0.500ms in the first line vs 0.01s in the second? Was the application paused (because of STW) for 0.500ms or for 10ms (0.01s)? I tried tools like GCeasy, it shows max pause time of 10ms, and in cases where Real = 0.00, GCeasy shows min pause of 0ms. I wonder, what kind of pause is 0.500ms representing then?
[9.090s] [info] [gc] GC(25)暂停年轻(正常)(G1 疏散暂停)77M-> 2M(128M)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)用户= 0.00s Sys = 0.00s实际= 0.01s
[9.090s][info][gc,cpu ] GC(25) User=0.00s Sys=0.00s Real=0.01s
gc.logs与JMC中GC暂停的时间差
GC Pause time difference in gc.logs vs in JMC
0.687毫秒在gc.log中暂停
0.687ms pause in gc.log
根据JMC，为1.331秒
Where as 1.331 second according to JMC
推荐答案
我不确定是否应该将其发布为答案，因为这是 my 对此日志的理解，但是似乎太大了，无法发表评论.
I am not sure if I should post this as an answer, because this is my understanding of this log, but it would be too big for a comment it seems.
如果用G1GC的眼睛看，STW事件的总时间为0.500ms，如果以Shenandoah为例，则既不是0.500ms也不是10ms.使用G1GC时，使用Shenandoah将STW event视为0.500ms，将导致0.500ms + delta；否则，将显示0.500ms + delta.其中delta是将所有java threads带到safepoint所花费的累积时间(也称为TTSP-到达安全点的时间)+该safepoint所需的清理工作.可能是一张图片会使此操作变得容易:
The total time of the STW event was 0.500ms if you look with the eyes of G1GC and was neither 0.500ms nor 10ms if you take Shenandoah for example. When you use G1GC, STW event is treated as 0.500ms, using Shenandoah, will result in 0.500ms + delta; where this delta will be the cumulative time it took to bring all java threads to a safepoint (also called TTSP - time to safe point) + whatever clean-up was needed for that safepoint. May be a picture will make this easier:
|------|------------------------|---------|
| TTPS | G1 Evacuation Pause | CleanUp |
|------|------------------------|---------|
G1GC仅将STW Event.例如，Shenandoah会将整个事件视为STW事件(所有3个区域).谁是对的?我将由您决定.
G1GC treats as the STW Event the G1 Evacuation Pause region only. Shenandoah for example, treats the entire thing as the STW event (all 3 regions). Who is right? I will leave this up to you to decide.
例如，您可以通过-Xlog:safepoint*为G1GC启用安全点粒度.
You can enable the safepoint granularity for G1GC via -Xlog:safepoint*, for example.
我猜您正在使用的工具有其自己的意见"，哦，怎么看待日志产生的每次时间?但这绝对不是10 ms.为什么?正如您已经看到的(在评论中所说)，有时您会在日志中看到类似的内容:
The tools that you are using have their own "opinion" oh how to treat each time produced by the logs, I guess; but it is absolutely not 10 ms. Why? As you have seen already (as you say in comments) there are times when you will get something like this in logs:
[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时间.
Notice the Real=0.00s. Does this mean there was no pause? Of course not, it just means there was no cpu time spent.
这篇关于G1GC日志中的时间的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
