проблема с файлом журнала jvm verbosegc

У нас есть сервер Glassfish на сервере Linux с включенным verbose:gc с выводом в файле gc.log.

Мы используем флаг -XX:+PrintGCDetails. Сгенерированный файл содержит такие строки:

14.796: [GC [PSYoungGen: 432125K->45845K(454336K)] 537435K->153491K(624832K), 0.0304470 secs] [Times: user=0.12 sys=0.01, real=0.02 secs]
15.337: [GC [PSYoungGen: 269819K->25031K(464768K)] 377465K->154113K(635264K), 0.0361400 secs] [Times: user=0.10 sys=0.01, real=0.03 secs]
15.373: [Full GC (System) [PSYoungGen: 25031K->0K(464768K)] [PSOldGen: 129081K->123718K(170496K)] 154113K->123718K(635264K) [PSPermGen: 92038K->92038K(184384K)], 0.3855460 secs]

Как видите, последняя строка не содержит части [Times: ...]. Строка события GC не полностью записывается в файл журнала, потому что, когда происходит следующее событие GC, записывается часть [Times: ...] предыдущей строки, а затем записывается еще одна неполная строка, что дает нам что-то вроде:

14.796: [GC [PSYoungGen: 432125K->45845K(454336K)] 537435K->153491K(624832K), 0.0304470 secs] [Times: user=0.12 sys=0.01, real=0.02 secs]
15.337: [GC [PSYoungGen: 269819K->25031K(464768K)] 377465K->154113K(635264K), 0.0361400 secs] [Times: user=0.10 sys=0.01, real=0.03 secs]
15.373: [Full GC (System) [PSYoungGen: 25031K->0K(464768K)] [PSOldGen: 129081K->123718K(170496K)] 154113K->123718K(635264K) [PSPermGen: 92038K->92038K(184384K)], 0.3855460 secs] [Times: user=0.38 sys=0.01, real=0.39 secs]
3617.352: [GC [PSYoungGen: 431872K->8052K(439936K)] 585800K->161981K(718144K), 0.0085710 secs]

Поскольку строка не закончена, возврат каретки отсутствует, поэтому строка не отображается в таких инструментах, как multitail

Используя флаг -XX:+PrintGC, у нас больше нет этой проблемы. Но так как нам нужна полная информация, это не очень хорошее решение.

Версия JVM, работающая на Linux:

java version "1.6.0_26"
Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)

Итак, вопрос: можно ли заставить JVM записывать строку журнала (своего рода флеш-трюк)? Или возможно иметь детали GC без последней части?


java jvm glassfish jvm-hotspot verbosegc
person cporte    schedule 17.10.2012    source источник
comment
Столкнулся с той же проблемой (версия Java 1.6.0_34). Удалось ли вам найти обходной путь или фактическое решение?   -  person pmac72    schedule 24.01.2013
comment
Еще ничего. Нашим следующим шагом будет попытка использовать JVM версии 1.7, возможно, в течение следующих 3 месяцев. Держи меня на связи, если что-то найдешь   -  person cporte    schedule 24.01.2013
comment
Возможность обновления 1.7 довольно далека для моей ситуации, но, пожалуйста, отправьте сообщение, если это исправит это. Я знаю, что в версии 1.7 появились новые функции/опции ведения журнала gc.   -  person pmac72    schedule 25.01.2013

Ответы (1)


arrow_upward
2
arrow_downward

Проверка исходников OpenJDK 6/7 кажется, что -XX:+PrintGCDetails не сбрасывается

TraceCPUTime::~TraceCPUTime() {
  if (_active) {
    bool valid = false;
    if (!_error) {
      double real_secs;                 // walk clock time
      double system_secs;               // system time
      double user_secs;                 // user time for all threads

      double real_time, user_time, system_time;
      valid = os::getTimesSecs(&real_time, &user_time, &system_time);
      if (valid) {

        user_secs = user_time - _starting_user_time;
        system_secs = system_time - _starting_system_time;
        real_secs = real_time - _starting_real_time;

        _logfile->print(" [Times: user=%3.2f sys=%3.2f, real=%3.2f secs] ",
          user_secs, system_secs, real_secs);

      } else {
        _logfile->print("[Invalid result in TraceCPUTime]");
      }
    } else {
      _logfile->print("[Error in TraceCPUTime]");
    }
     if (_print_cr) {
      _logfile->print_cr("");
    }
  }
}

и это исправлено в OpenJDK 8 благодаря этому отчету об ошибке.

TraceCPUTime::~TraceCPUTime() {
  if (_active) {
    bool valid = false;
    if (!_error) {
      double real_secs;                 // walk clock time
      double system_secs;               // system time
      double user_secs;                 // user time for all threads

      double real_time, user_time, system_time;
      valid = os::getTimesSecs(&real_time, &user_time, &system_time);
      if (valid) {

        user_secs = user_time - _starting_user_time;
        system_secs = system_time - _starting_system_time;
        real_secs = real_time - _starting_real_time;

        _logfile->print(" [Times: user=%3.2f sys=%3.2f, real=%3.2f secs] ",
           user_secs, system_secs, real_secs);

      } else {
        _logfile->print("[Invalid result in TraceCPUTime]");
      }
    } else {
      _logfile->print("[Error in TraceCPUTime]");
    }
    if (_print_cr) {
      _logfile->print_cr("");
    }
    _logfile->flush();
  }
}

Может быть, он будет перенесен, если кто-то запишет его против 6/7.

person fglez    schedule 05.03.2013
comment
Отличный ответ! Основываясь на этом, я проверил и обнаружил, что: /jdk7u/jdk7u/hotspot/rev/8e478700068f Кажется, они перенесли его на JDK7. Судя по дате, я бы сказал, что он доступен начиная с jdk7u12 или jdk7u13. - person cporte; 06.03.2013