What does this Java G1 GC log message mean?

user_62720 0
Viewed 497

This is from a Java process running with a 24G heap, G1GC, on some open source variant of JDK 11.

[info ][gc,marking     ] GC(132605) Concurrent Mark (728435.456s, 728445.080s) 9624.269ms
  1. Concurrent mark is really concurrent in G1 (except for the remarking time)? Meaning that the time being measured here is not pause time.
  2. What does this time represent? Is this CPU time? Wall clock time?

I've done some googling around to see what this might be, but I never find what this particular message means.

garbage-collection java
2 Answers

  1. Yes, its not a pause time.
    You can also add safepoint logger to see any additional pauses.
    But otherwise I think all actual pauses are logged in clear way, stating what part is a pause. For example Pause Young (Mixed) (G1 Evacuation Pause)

  2. It should be GC(number of GC) Concurrent Mark(clock start time, clock end time) time
    Where click time is relative time from aplication launch. And time at the end is just how long it took, also real wall time. You can verify this stright in the source: 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));

If you have enough of logging enabled you should see a line:
[info ][gc,marking ] GC(132605) Concurrent Mark 728435.456s or
[728435.456s][info ][gc,marking ] GC(132605) Concurrent Mark 728435.456s
Somehwere above, marking the beginning of concurrent mark. (the time at the beginning here would be uptime decorator to gc logger)

printed by one of first lines in sources above:

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

that is CPU time. In general, the name concurrent is there for a reason. Let's see that via an example:

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());
        }
    }
}

And invoke it via:

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

In my particular run, the relevant to your question logging starts at this line:

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

So GC says, OK time to start a "concurrent mark". Notice that is already knows the roots (concurrent marking has to start from somewhere, after all). The root knowledge (where the roots are) was computed in the previous GC cycle.

Then look at where that GC(11) cycle continues:

[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

Notice that there were other 11 gc cycles (22 -> 11), while this concurrent one was executing.

I'd like also to point you to this log:

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

This is a remark phase, some attribute this to concurrent phase, which is a STW phase; but notice that G1 track it's time individually.

user_10593720
Related