这个Java日志消息是什么意思？

Question

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

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

1. 并发标记实际上在G1中是并发的(除了复述时间)？这意味着这里测量的时间不是暂停时间。

，

1. ，这个时间代表什么？现在是CPU时间吗？挂钟时间？

我已经做了一些搜索，看看这可能是什么，但我从来没有找到这个特定的信息意味着什么。

Answer 1

1. 是的，现在不是暂停时间。

您还可以添加safepoint记录器来查看任何其他暂停。

但是，否则我认为所有实际的暂停都是以明确的方式记录的，说明什么部分是暂停。例如，Pause Young (Mixed) (G1 Evacuation Pause)

1. 它应该是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中验证这个stright

        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

上面有一些标记，标志着并行标记的开始。(这里开头的时间将是gc记录器的正常运行时间装饰器)

由上述来源的第一行之一印刷的：

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

Answer 2

那是CPU时间。一般来说，并发这个名字的存在是有原因的。让我们通过一个例子来看看：

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

注意，在执行此并发周期时，还存在其他11 gc周期(22 -> 11)。

我还想让你看看这个日志：

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

这是一个备注阶段，有些人将其归因于并发阶段，这是一个STW阶段；但是请注意，G1单独跟踪时间。