Блог

Главная - Вопросы по программированию - Что означает это сообщение журнала Java G1 GC?

Что означает это сообщение журнала Java G1 GC?

#java #garbage-collection

Вопрос:

Это из процесса Java, работающего с кучей 24G, G1GC, на каком-то варианте JDK 11 с открытым исходным кодом.

 [info ][gc,marking     ] GC(132605) Concurrent Mark (728435.456s, 728445.080s) 9624.269ms
  1. Параллельная метка действительно параллельна в G1 (за исключением времени замечания)? Это означает, что время, измеряемое здесь, не является временем паузы.
  2. Что представляет собой это время? Это время процессора? Время настенных часов?

Я немного погуглил, чтобы понять, что это может быть, но так и не нашел, что означает это конкретное сообщение.

Ответ №1:

  1. Да, это не время для паузы.
    Вы также можете добавить регистратор safepoint, чтобы видеть любые дополнительные паузы.
    Но в остальном я думаю, что все фактические паузы регистрируются четко, указывая, какая часть является паузой. Например Pause Young (Mixed) (G1 Evacuation Pause)
  2. Это должно быть 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
Что-то было выше, отмечая начало параллельной метки. (время в начале здесь будет декоратором времени безотказной работы для регистратора gc)

напечатано одной из первых строк в источниках выше:

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

Комментарии:

1. Спасибо за ссылку на источник.

Ответ №2:

это время процессора. В общем, название 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 говорит, что пришло время начать «параллельную отметку». Обратите внимание, что is уже знает корни (в конце концов, параллельная маркировка должна откуда-то начинаться). Знание корня (где находятся корни) было вычислено в предыдущем цикле 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 отслеживает время индивидуально.

Метки: