分析gc日志

Question

我正在使用-XX:+PrintGCApplicationStoppedTime和-XX:+PrintGCApplicationConcurrentTime选项打开gc日志记录.

但发现只有PrintGCApplicationStoppedTime经过-XX:+PrintGCDetails命令打印的gc日志的4 0r 5打印后我的实际细节!

根据定义,PrintGCApplicationStoppedTime打印应用程序停止每个gc的时间.

但我不清楚为什么它打印如下所示的例子.

是因为

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

(要么)

日志文件将由不同的gc线程记录.我使用Concurrent扫描完整的GC和年轻一代的ParNew

我的应用是web应用程序.

O/p模式 - 我是这样的:

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]

Answer 1

不幸的PrintGCApplicationStoppedTime是,这个JVM选项的名称是误导性的.

实际上它会打印安全点内部所花费的时间.安全点暂停不仅是由于垃圾收集,还有许多其他原因:

• 去优化
• 有偏见的锁定撤销
• 线程转储
• 堆检查
• 类重定义
• 等(见清单)

即使没有请求的VM操作,安全点也可能定期发生,以便对空闲监视器进行放气,执行某些JIT清理等等.请参阅-XX:GuaranteedSafepointIntervalVM选项(默认为1000毫秒).

使用-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1转储有关safepoints的更多信息.