分析GC日志

Question

我正在使用-XX:+PrintGCApplicationStoppedTime和-XX:+PrintGCApplicationConcurrentTime选项来开启垃圾回收日志记录。

但只有在打印了 4 或 5 次 PrintGCApplicationStoppedTime 后，我才能通过 -XX:+PrintGCDetails 命令打印出实际的 gc 日志细节！

按定义，PrintGCApplicationStoppedTime 会为每个 gc 打印应用程序停止时间。

但我不清楚为什么它会像下面的示例一样打印。

这是因为

PrintGCApplicationStoppedTime 只是在到达每个安全点后才打印

(还是)

日志文件将由不同的 gc 线程记录。 我正在使用 Concurrent sweep 进行完整的 GC 和 ParNew 进行年轻代 GC。

我的应用程序是 Web 应用程序。

输出模式- 我得到的结果是这样的：

Application time: 0.3847031 seconds
Total time for which application threads were stopped: 0.3135419 seconds
Application time: 0.1520723 seconds
Total time for which application threads were stopped: 0.1993920 seconds
Application time: 0.1188219 seconds
Total time for which application threads were stopped: 0.1993920 seconds
Application time: 0.1188219 seconds
Total time for which application threads were stopped: 0.1993920 seconds
Application time: 0.1188219 seconds
Total time for which application threads were stopped: 0.1993920 seconds
Application time: 0.1188219 seconds
1.229: [GC 1.229: [ParNew: 256000K->51200K(256000K), 0.1509756 secs] 426536K->334728K(997376K), 0.1510198 secs] [Times: user=0.85 sys=0.07, real=0.15 secs]

- Jeyshri Gopalakrishnan

Answer 1

不幸的是，PrintGCApplicationStoppedTime 是这个JVM选项的误导性名称。

实际上，它打印的是在安全点内花费的时间。 安全点暂停不仅由于垃圾收集而发生，还由于许多其他原因：

• 去优化
• 偏向锁撤销
• 线程转储
• 堆检查
• 类重定义
• 等等。 (请参见列表)

即使没有请求的VM操作，安全点也可能定期发生，以便紧缩空闲监视器、执行某些JIT清理等。 请参阅-XX:GuaranteedSafepointInterval VM选项(默认为1000毫秒)。

使用-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1来转储有关安全点的更多信息。

- apangin