java - jvm verbosegc 日志文件问题

Question

我们在 linux 服务器上有一个 Glassfish 服务器，它打开了 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 详细信息？

Answer 1

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

由于这个 bug report，它在 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 提交它，它可能会被反向移植。