为什么两个小GC之间有多个“停止应用程序线程的总时间”日志？

Question

我使用以下设置运行一个java应用程序：

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

我以为每次发生GC时，打开-XX:+PrintGCApplicationStoppedTime开关都会输出应用程序停止的时间，但是会得到多行日志，显示应用程序在两个小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引起的？

如果我想知道我的申请在GCs期间停止的总时间，我应该把所有这些日志中的时间加起来吗？

Answer 1

使用-XX:+PrintSafepointStatistics找出每个safepoint的原因，this answer中的链接显示在哪里可以获得可导致safepoint到达的完整列表。

Answer 2

这个日志显示了停止应用程序的所有原因，而不仅仅是GCs。减少这种情况的一种方法是关闭偏置锁定(与GCs无关)；

试一试

-XX:-UseBiasedLocking