Java G1 GC 日志消息是什么意思？

Question

这是来自 Java 进程运行 24G 堆 G1GC，在 JDK 11 的一些开源变体上。

[info ][gc,marking     ] GC(132605) Concurrent Mark (728435.456s, 728445.080s) 9624.269ms

并发标记在G1中真的是并发的（remarking时间除外）？也就是说这里测量的时间不是暂停时间。
这个时间代表什么？这是CPU时间吗？挂钟时间？

我在谷歌上搜索了一下，看看这可能是什么，但我从来没有找到这个特定消息的意思。

Answer 1

是的，这不是暂停时间。
您还可以添加安全点记录器以查看任何额外的暂停。
但除此之外，我认为所有实际的停顿都以清晰的方式记录下来，说明哪部分是停顿。例如Pause Young (Mixed) (G1 Evacuation Pause)
应该是GC(number of GC) Concurrent Mark(clock start time, clock end time) time
点击时间是应用程序启动的相对时间。最后的时间就是花了多长时间，也是真正的墙时间。您可以直接在源代码中验证这一点：https://github.com/openjdk/jdk/blob/7ccf4358256a0fef895e4081f90b04f71d21bf9d/src/hotspot/share/gc/g1/g1ConcurrentMarkThread.cpp#L184-L220

        log_info(gc, marking)("Concurrent Mark (%.3fs, %.3fs) %.3fms",
                              TimeHelper::counter_to_seconds(mark_start),
                              TimeHelper::counter_to_seconds(mark_end),
                              TimeHelper::counter_to_millis(mark_end - mark_start));

如果您启用了足够的日志记录，您应该会看到一行：
[info ][gc,marking ] GC(132605) Concurrent Mark 728435.456s 或
[728435.456s][info ][gc,marking ] GC(132605) Concurrent Mark 728435.456s
Somehwere上面，标记并发标记的开始。（这里开始的时间将是 gc logger 的 uptime decorator）

由以上来源中的第一行之一打印：

      log_info(gc, marking)("Concurrent Mark (%.3fs)",
                            TimeHelper::counter_to_seconds(mark_start));

Answer 2

也就是CPU时间。一般来说，concurrent 这个名字是有原因的。让我们通过一个例子来看一下：

public class Del {

    public static void main(String[] args) {

        Map<String, Integer> map = new HashMap<>();

        while (true) {
            map.put(new Random().toString(), new Random().nextInt());
        }
    }
}

并通过以下方式调用它：

java -Xms50M -Xmx50M "-Xlog:heap*=debug" "-Xlog:gc*=debug" Del.java

在我的特定运行中，与您的问题相关的记录从这一行开始：

....
[0.667s][info ][gc        ] GC(11) Concurrent Mark Cycle
....
[0.668s][info ][gc,marking] GC(11) Concurrent Mark From Roots
....

所以 GC 说，是时候启动“并发标记”了。请注意，它已经知道了根源（毕竟并发标记必须从某处开始）。根知识（根所在的位置）是在上一个 GC 周期中计算的。

然后查看 GC(11) 循环继续的位置：

[0.739s][info ][gc      ] GC(22) Pause Young (Normal) (G1 Evacuation Pause) 43M->42M(50M) 4.566ms
[0.739s][info ][gc,cpu  ] GC(22) User=0.01s Sys=0.00s Real=0.00s
[0.739s][debug][gc,ref  ] GC(11) Preclean WeakReferences 4.713ms
...
[0.739s][info ][gc,start] GC(11) Pause Remark

注意有 other 11 个 gc 循环（22 -> 11），而这个并发循环正在执行。

我还想向您指出此日志：

[0.739s][info ][gc,start] GC(11) Pause Remark

这是remark阶段，有人认为这是concurrent阶段，是STW阶段；但请注意 G1 单独跟踪时间。

Java G1 GC 日志消息是什么意思？

What does this Java G1 GC log message mean?

java

garbage-collection