jvm verbosegc log file issue

Question

We have a Glassfish server on a linux server with verbose:gc on, with the output in a gc.log file.

We use the flag -XX:+PrintGCDetails. The generated file contains lines like this :

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]

As you can see, the last line doesn't contains the [Times: ...] part. The GC event line is not fully written to the log file, because when the next GC event occurs, the [Times: ...] part of the previous line is written, and then another partial line is written, giving us something like :

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]

As the line is not finished, no carriage returns is present, so the line is not displayed in tools like multitail

Using the -XX:+PrintGC flag, we don't have this problem anymore. But as we need the full details, it's not a good solution.

JVM Version, running on 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)

So the question is: is it possible to force the JVM to write the log line (a kind of flush trick) ? Or is it possible to have the GC details without the last part ?

Running into the same problem (java version "1.6.0_34"). Did you manage to find a work around or actual solution? — pmac72, Jan 23 '13 at 21:00
Still nothing. Our next step will be to try with a 1.7 JVM, maybe within the next 3 months. Keep me in touch if you find something — cporte, Jan 23 '13 at 21:18
The possibility of a 1.7 upgrade is pretty far off for my situation, but please post back if that fixes it. I know there's new gc logging functionality/options in 1.7. — pmac72, Jan 25 '13 at 00:34

fglez · Accepted Answer · 2013-03-05T17:29:05.390

Checking OpenJDK 6/7 sources it seems -XX:+PrintGCDetails is not flushing

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

and it's fixed in OpenJDK 8 thanks to this bug report.

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

Maybe it gets backported if someone files it against 6/7.

Great answer! Based on that I check and found that: http://hg.openjdk.java.net/jdk7u/jdk7u/hotspot/rev/8e478700068f It seems they backported it to JDK7. Based on the date, I would say it's available starting from jdk7u12 or jdk7u13 — cporte, Mar 05 '13 at 21:18

jvm verbosegc log file issue

1 Answers1