我们在 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 详细信息?
最佳答案
检查 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 提交它,也许它会被向后移植。
关于java - jvm verbosegc 日志文件问题,我们在Stack Overflow上找到一个类似的问题: https://stackoverflow.com/questions/12935329/