Search code examples
javagarbage-collection

What does this Java G1 GC log message mean?

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.

Solution

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