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

Why are there multiple "Total time for which application threads were stopped" logs between two minor GCs

提问by user868872

I'm running a java application with the following settings:

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

-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

I thought turning on -XX:+PrintGCApplicationStoppedTime switch would output how much time the application is stopped each time a GC occurs, but a got multiple lines of logs telling how much time the application is stopped between two minor GCs, like the following logs:

我以为打开 -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)
}

Why are there multiple consecutive lines of "Total time for which the application threads were stopped" and "Application Time" logs between two minor GCs. What is each line of them related to? A GC that is not outputted in detail? or are they not caused by GC?

为什么在两次minor GC之间会出现多行“应用线程停止的总时间”和“应用时间”日志。它们的每一行都与什么相关？一个没有详细输出的GC？或者它们不是由GC引起的？

If I want to know the total time my application stopped for during GCs, should I sum the time in all these logs?

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

回答by Matt

Use -XX:+PrintSafepointStatisticsto find out the cause of each safepoint, links in this answershow where to get a full list of what can cause a safepoint to be reached.

使用-XX:+PrintSafepointStatistics找出每个还原点的原因，在链接这个答案要达到表演在哪里得到的东西可能会导致一个还原点的完整列表。

回答by Peter Lawrey

This log shows you every reason an application is stopped, not just for GCs. One way to reduce these is to turn off biased locking (Nothing to do with GCs) ;)

此日志显示应用程序停止的所有原因，而不仅仅是 GC。减少这些的一种方法是关闭偏向锁定（与 GC 无关）；)

Try

尝试

-XX:-UseBiasedLocking