Почему некоторые строки в моем журнале GC показывают только одно значение размера кучи?

Question

Большинство строк в моем журнале GC выглядят так:

203,558: [GC 326391K-> 324672K (4192192K), 0,0452610 с]

Размер в скобках - это «зафиксированная куча», или (приблизительно) размер процесса, видимый ОС. Два числа перед этим («a-> b») показывают использование кучи до и после GC.

Теперь, регулярно, я получаю такие строки:

42381,926: [GC 10996274K (12565888K), 0,0651560 с]

Означают ли это, что использование кучи не было изменено GC, или это другое сообщение? Я посмотрел учебник по настройке Oracle GC и еще одну страницу, посвященную выводу GC , но не смог найти объяснение этого типа сообщений.

Я использую Sun JVM (1.6.0.25), Concurrent Collector (-XX:+UseConcMarkSweepGC) и единственная опция запуска, связанная с выводом, - -Xloggc:gc.log.

Answer 1

Я искал "secs" в исходном коде обновления 23 JDK 1.6 (для самой последней версии 1.6, в которой я смог его найти) и для выражения "[^"] * -> [^ "] *" черезПапки с кодом GC в надежде найти лидера.Я также искал код OpenJDK 1.7.Затем я попытался найти во всей папке HotSpot «[^»] * -> [^ »] *«?. * Secs.Тем не менее, единственная строка журналирования GC, которую я обнаружил и которая, похоже, имеет отдаленное отношение к тому, что вы видите, это

gclog_or_tty->print("[%s-concurrent-%s: %3.3f/%3.3f secs]",
             _collector->cmsGen()->short_name(),
             _phase, _collector->timerValue(), _wallclock.seconds());

Это находится в concurrentMarkSweepGeneration.cpp.Это даже не похоже на формат, который вы видели.Либо я не очень хорошо ищу, либо что-то изменилось между обновлением 23 и обновлением 25, касающимся регистрации GC.

Если у кого-то есть более четкое представление о том, где искать или что искать, я буду радОбязатьЭто похоже на то, что вы получаете.Я не очень хорош в интерпретации этого кода, но я бы сказал, что вы видите просто строку журнала, показывающую текущее использование кучи, за которым следует фиксированный размер кучи в скобках, не более того.В основном та же информация, но без использования перед сборкой мусора.

Answer 2

Я думаю, что эта строка инициируется TraceTime в timer.cpp, который вызывается из CMS (concurrentMarkSweepGeneration.cpp do_CMS_operation) и ParNew (parNewGeneration.cpp collect). Этот код кажется источником

void ConcurrentMarkSweepGeneration::printOccupancy(const char *s) {
    GenCollectedHeap* gch = GenCollectedHeap::heap();
    if (PrintGCDetails) {
      if (Verbose) {
        gclog_or_tty->print(" [%d %s-%s: "SIZE_FORMAT"("SIZE_FORMAT")]",
          level(), short_name(), s, used(), capacity());
    } else {
        gclog_or_tty->print(" [%d %s-%s: "SIZE_FORMAT"K("SIZE_FORMAT"K)]",
          level(), short_name(), s, used() / K, capacity() / K);
      }
    }
    if (Verbose) {
      gclog_or_tty->print(" "SIZE_FORMAT"("SIZE_FORMAT")",
                gch->used(), gch->capacity());
    } else {
      gclog_or_tty->print(" "SIZE_FORMAT"K("SIZE_FORMAT"K)",
              gch->used() / K, gch->capacity() / K);
    }
}

Следовательно, это заявление об общей занятости кучи (сумме всех поколений) вместе с временем, прошедшим во время текущей операции GC. Печатное время выглядит как настенное время, так как таймер (os::elapsed_counter, например, это gettimeofday в Linux) запускается, когда создается экземпляр TraceTime и останавливается / печатается, когда он уничтожается.

Я рекомендую вам добавить verbose:gc, чтобы получить больше информации, если хотите.

Answer 3

Можете ли вы перечислить все параметры jvm для gc-looging?

Глядя на ваш вывод, я не думаю, что вы используете

-verbose: gc -XX: + PrintGCTimeStamps -XX:+ PrintGCDetails

Также проверьте

Объяснение операторов журнала Tomcat GC

Сообщения журнала сбора мусора Java