java - 为什么两次minor GC之间有多个 "Total time for which application threads were stopped"日志

Question

我正在运行具有以下设置的 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)
}

为什么两次minor GC之间有多行连续的“Total time for which the application threads are stopped”和“Application Time”日志。它们的每一行与什么有关？没有详细输出的GC？还是不是GC引起的？

如果我想知道我的应用程序在 GC 期间停止的总时间，我应该将所有这些日志中的时间相加吗？

Answer 1

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