首页 文章

为什么两个次要GC之间存在多个“应用程序线程停止的总时间”日志

提问于
浏览
10

我正在使用以下设置运行java应用程序:

-Xms1G -Xmx2G -Xdebug -Xloggc:/usr/local/resin/log/gc.log -XX:PrintGCDetails -XX:PermSize = 150M -XX:PrintGCTimeStamps -XX:PrintTenuringDistribution -XX:PrintGCApplicationStoppedTime -XX:PrintGCApplicationConcurrentTime -XX :PrintHeapAtGC -XX:UseConcMarkSweepGC

我想打开-XX:PrintGCApplicationStoppedTime开关会输出每次GC发生时应用程序停止的时间,但是有多行日志告诉应用程序在两个次要GC之间停止了多长时间,如下面的日志:

Total time for which application threads were stopped: 0.0043330 seconds
Application time: 1410.4236260 seconds
{Heap before GC invocations=636 (full 2):
 par new generation   total 38336K, used 34123K [0x00002aaab1a60000, 0x00002aaab43f0000, 0x00002aaab43f0000)
  eden space 34112K, 100% used [0x00002aaab1a60000, 0x00002aaab3bb0000, 0x00002aaab3bb0000)
  from space 4224K,   0% used [0x00002aaab3bb0000, 0x00002aaab3bb2de0, 0x00002aaab3fd0000)
  to   space 4224K,   0% used [0x00002aaab3fd0000, 0x00002aaab3fd0000, 0x00002aaab43f0000)
 concurrent mark-sweep generation total 1006016K, used 208278K [0x00002aaab43f0000, 0x00002aaaf1a60000, 0x00002aab31a60000)
 concurrent-mark-sweep perm gen total 153600K, used 90763K [0x00002aab31a60000, 0x00002aab3b060000, 0x00002aab3b060000)
122682.024: [GC 122682.024: [ParNew
Desired survivor size 2162688 bytes, new threshold 4 (max 4)
- age   1:       4896 bytes,       4896 total
- age   2:       2272 bytes,       7168 total
: 34123K->10K(38336K), 0.0037720 secs] 242402K->208291K(1044352K), 0.0038540 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap after GC invocations=637 (full 2):
 par new generation   total 38336K, used 10K [0x00002aaab1a60000, 0x00002aaab43f0000, 0x00002aaab43f0000)
  eden space 34112K,   0% used [0x00002aaab1a60000, 0x00002aaab1a60000, 0x00002aaab3bb0000)
  from space 4224K,   0% used [0x00002aaab3fd0000, 0x00002aaab3fd2bf8, 0x00002aaab43f0000)
  to   space 4224K,   0% used [0x00002aaab3bb0000, 0x00002aaab3bb0000, 0x00002aaab3fd0000)
 concurrent mark-sweep generation total 1006016K, used 208280K [0x00002aaab43f0000, 0x00002aaaf1a60000, 0x00002aab31a60000)
 concurrent-mark-sweep perm gen total 153600K, used 90763K [0x00002aab31a60000, 0x00002aab3b060000, 0x00002aab3b060000)
}
Total time for which application threads were stopped: 0.0044760 seconds
Application time: 317.6313600 seconds
Total time for which application threads were stopped: 0.0004960 seconds
Application time: 86.5483550 seconds
Total time for which application threads were stopped: 0.0005090 seconds
Application time: 0.0001400 seconds
Total time for which application threads were stopped: 0.0001360 seconds
Application time: 46.6827150 seconds
Total time for which application threads were stopped: 0.0004430 seconds
Application time: 74.2952540 seconds
Total time for which application threads were stopped: 0.0004940 seconds
Application time: 0.0001300 seconds
Total time for which application threads were stopped: 0.0001130 seconds
Application time: 0.0001290 seconds
Total time for which application threads were stopped: 0.0001290 seconds
Application time: 51.1991810 seconds
Total time for which application threads were stopped: 0.0004860 seconds
Application time: 190.7426760 seconds
Total time for which application threads were stopped: 0.0004930 seconds
Application time: 0.0000750 seconds
Total time for which application threads were stopped: 0.0001000 seconds
Application time: 55.4635280 seconds
Total time for which application threads were stopped: 0.0004900 seconds
Application time: 180.7308270 seconds
Total time for which application threads were stopped: 0.0005060 seconds
Application time: 60.9953830 seconds
Total time for which application threads were stopped: 0.0005490 seconds
Application time: 60.9591480 seconds
Total time for which application threads were stopped: 0.0006410 seconds
Application time: 292.0577720 seconds
{Heap before GC invocations=637 (full 2):
 par new generation   total 38336K, used 34122K [0x00002aaab1a60000, 0x00002aaab43f0000, 0x00002aaab43f0000)
  eden space 34112K, 100% used [0x00002aaab1a60000, 0x00002aaab3bb0000, 0x00002aaab3bb0000)
  from space 4224K,   0% used [0x00002aaab3fd0000, 0x00002aaab3fd2bf8, 0x00002aaab43f0000)
  to   space 4224K,   0% used [0x00002aaab3bb0000, 0x00002aaab3bb0000, 0x00002aaab3fd0000)
 concurrent mark-sweep generation total 1006016K, used 208280K [0x00002aaab43f0000, 0x00002aaaf1a60000, 0x00002aab31a60000)
 concurrent-mark-sweep perm gen total 153600K, used 90763K [0x00002aab31a60000, 0x00002aab3b060000, 0x00002aab3b060000)
124099.341: [GC 124099.341: [ParNew
Desired survivor size 2162688 bytes, new threshold 4 (max 4)
- age   1:      20680 bytes,      20680 total
- age   3:        808 bytes,      21488 total
: 34122K->25K(38336K), 0.0036900 secs] 242403K->208305K(1044352K), 0.0037700 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap after GC invocations=638 (full 2):
 par new generation   total 38336K, used 25K [0x00002aaab1a60000, 0x00002aaab43f0000, 0x00002aaab43f0000)
  eden space 34112K,   0% used [0x00002aaab1a60000, 0x00002aaab1a60000, 0x00002aaab3bb0000)
  from space 4224K,   0% used [0x00002aaab3bb0000, 0x00002aaab3bb6488, 0x00002aaab3fd0000)
  to   space 4224K,   0% used [0x00002aaab3fd0000, 0x00002aaab3fd0000, 0x00002aaab43f0000)
 concurrent mark-sweep generation total 1006016K, used 208280K [0x00002aaab43f0000, 0x00002aaaf1a60000, 0x00002aab31a60000)
 concurrent-mark-sweep perm gen total 153600K, used 90763K [0x00002aab31a60000, 0x00002aab3b060000, 0x00002aab3b060000)
}

为什么有两个连续行“应用程序线程停止的总时间”和“应用程序时间”在两个次要GC之间记录 . 它们的每一行有什么关系?没有详细输出的GC?或者它们不是由GC引起的?

如果我想知道我的应用程序在GC期间停止的总时间,我应该在所有这些日志中总结时间吗?

2 回答

  • 1

    此日志显示应用程序停止的所有原因,而不仅仅是GC . 减少这些的一种方法是关闭偏置锁定(与GC无关);)

    尝试

    -XX:-UseBiasedLocking
    
  • 4

    使用 -XX:+PrintSafepointStatistics 查找每个安全点的原因,this answer中的链接显示从何处获取可以导致安全点到达的完整列表 .

相关问题