分析gc日志 [英] Analysis on gc logs

问题描述

使用XX：+ PrintGCApplicationStoppedTime -XX：+ PrintGCApplicationConcurrentTime添加到我的gc日志中！

但是发现只有在打印完4G或5G PrintGCApplicationStoppedTime后，通过-XX打印：+ PrintGCDetails命令！

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

但是Iam不清楚它为什么打印如下所示的示例

是因为

PrintGCApplicationStoppedTime只是在每个保险柜点到达

（或）

日志文件将由不同的gc线程记录！
Im使用并发扫描完成GC和ParNew的年轻一代

我的应用程序是web应用程序！

 申请时间：0.3847031秒
总共花费的时间应用程序线程已停止：0.3135419秒
应用程序时间：0.1520723秒
应用程序线程停止的总时间：0.1993920秒
应用程序时间：0.1188219秒
应用程序线程的总时间已停止：0.1993920秒
应用程序时间：0.1188219秒
应用程序线程停止的总时间：0.1993920秒
应用程序时间：0.1188219秒
应用程序线程停止的总时间：0.1993920秒
应用时间：0.1188219秒
 1.229：[GC 1.229：[ParNew：256000K-> 51200K（256000K），0.1509756sec] 426536K-> 334728K（997376K），0.1510198secs] Times：user = 0.85 sys = 0.07，real = 0.15秒] 
  

解决方案

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

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

• 去优化


• 
  
• 线程转储


• 堆检查


• 类别redifinition


• 等。 （详见列表）

即使没有请求的虚拟机操作，Safepoint也可能会定期发生，以缩小闲置监视器的性能，执行某些JIT清理等等。
请参阅 -XX：GuaranteedSafepointInterval VM选项（默认为1000毫秒）。 使用 -XX：+ PrintSafepointStatistics -XX：PrintSafepointStatisticsCount = 1 转储更多关于安全点的信息。

Using XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime to my gc log !

But found that only after 4 0r 5 prints of PrintGCApplicationStoppedTime my actual details of gc logs printed through -XX:+PrintGCDetails command!

By definition PrintGCApplicationStoppedTime prints application stopped time for every gc

But Iam not clear why it prints like the example shown below

Is that because

PrintGCApplicationStoppedTime just prints after every safe point reach

(or)

the log file will be logged by different gc threads! Im using Concurrent sweep for full GC and ParNew for the young generation

My application is web application!

O/p Pattern- Im getting like this !

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]

解决方案

Unfortunately PrintGCApplicationStoppedTime is misleading name for this JVM option.

In fact it prints the time spent inside safepoints. Safepoint pauses occur not only due to Garbage Collection, but for many other reasons:

• Deoptimization
• Biased lock revocation
• Thread dump
• Heap inspection
• Class redifinition
• etc. (see the list)

Safepoints may happen periodically even without a requested VM operation in order to deflate idle monitors, perform certain JIT cleanup and so on. See -XX:GuaranteedSafepointInterval VM option (1000 milliseconds by default).

Use -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 to dump more information about safepoints.

这篇关于分析gc日志的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！