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 ?
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.