长时间的偶然 Young 垃圾收集暂停

Question

我们将 GC 调整为最小的“stop-the-world”暂停。 Perm 和 Tenured 世代表现良好。 Young 大部分时间工作正常，停顿通常不超过 500 毫秒（注意 [Times: user=0.35 sys=0.02, real=0.06 secs]）：

{Heap before GC invocations=11603 (full 60):
 par new generation   total 3640320K, used 3325226K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000)
  eden space 3235840K, 100% used [0x0000000600000000, 0x00000006c5800000, 0x00000006c5800000)
  from space 404480K,  22% used [0x00000006de300000, 0x00000006e3a4a898, 0x00000006f6e00000)
  to   space 404480K,   0% used [0x00000006c5800000, 0x00000006c5800000, 0x00000006de300000)
 concurrent mark-sweep generation total 4147200K, used 1000363K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000)
 concurrent-mark-sweep perm gen total 196608K, used 133030K [0x00000007f4000000, 0x0000000800000000, 0x0000000800000000)
2012-07-16T14:36:05.641+0200: 427048.412: [GC 427048.412: [ParNew
Desired survivor size 207093760 bytes, new threshold 4 (max 4)
- age   1:    8688880 bytes,    8688880 total
- age   2:   12432832 bytes,   21121712 total
- age   3:   18200488 bytes,   39322200 total
- age   4:   20473336 bytes,   59795536 total
: 3325226K->75635K(3640320K), 0.0559610 secs] 4325590K->1092271K(7787520K), 0.0562630 secs] [Times: user=0.35 sys=0.02, real=0.06 secs] 
Heap after GC invocations=11604 (full 60):
 par new generation   total 3640320K, used 75635K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000)
  eden space 3235840K,   0% used [0x0000000600000000, 0x0000000600000000, 0x00000006c5800000)
  from space 404480K,  18% used [0x00000006c5800000, 0x00000006ca1dcf40, 0x00000006de300000)
  to   space 404480K,   0% used [0x00000006de300000, 0x00000006de300000, 0x00000006f6e00000)
 concurrent mark-sweep generation total 4147200K, used 1016635K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000)
 concurrent-mark-sweep perm gen total 196608K, used 133030K [0x00000007f4000000, 0x0000000800000000, 0x0000000800000000)
}

但是，有时，通常是一天一次，我们会得到非常长的 Young 垃圾收集时间（注意 [Times: user=0.41 sys=0.01, real=5.51 secs]）：

{Heap before GC invocations=7884 (full 37):
 par new generation   total 3640320K, used 3304448K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000)
  eden space 3235840K, 100% used [0x0000000600000000, 0x00000006c5800000, 0x00000006c5800000)
  from space 404480K,  16% used [0x00000006c5800000, 0x00000006c9b00370, 0x00000006de300000)
  to   space 404480K,   0% used [0x00000006de300000, 0x00000006de300000, 0x00000006f6e00000)
 concurrent mark-sweep generation total 4147200K, used 1967225K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000)
 concurrent-mark-sweep perm gen total 189100K, used 112825K [0x00000007f4000000, 0x00000007ff8ab000, 0x0000000800000000)
2012-07-15T01:23:25.474+0200: 293088.245: [GC 293093.636: [ParNew
Desired survivor size 207093760 bytes, new threshold 4 (max 4)
- age   1:   30210472 bytes,   30210472 total
- age   2:   11614600 bytes,   41825072 total
- age   3:    8591680 bytes,   50416752 total
- age   4:    7779600 bytes,   58196352 total
: 3304448K->73854K(3640320K), 0.1158280 secs] 5271674K->2046454K(7787520K), 0.1181990 secs] [Times: user=0.41 sys=0.01, real=5.51 secs] 
Heap after GC invocations=7885 (full 37):
 par new generation   total 3640320K, used 73854K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000)
  eden space 3235840K,   0% used [0x0000000600000000, 0x0000000600000000, 0x00000006c5800000)
  from space 404480K,  18% used [0x00000006de300000, 0x00000006e2b1fb40, 0x00000006f6e00000)
  to   space 404480K,   0% used [0x00000006c5800000, 0x00000006c5800000, 0x00000006de300000)
 concurrent mark-sweep generation total 4147200K, used 1972599K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000)
 concurrent-mark-sweep perm gen total 189100K, used 112825K [0x00000007f4000000, 0x00000007ff8ab000, 0x0000000800000000)
}

以下是 jstat -gccause 的相关输出：

Timestamp         S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC                 
   293083.2  16.96   0.00  96.26  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      No GC               
   293083.2  16.96   0.00  96.26  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      No GC               
   293084.2  16.96   0.00  97.69  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      No GC               
   293085.3  16.96   0.00  98.32  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      No GC               
   293086.3  16.96   0.00  99.32  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      No GC               
Timestamp         S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC                 
   293087.3  16.96   0.00  99.55  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      No GC               
   293088.3  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293089.3  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293090.3  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293091.3  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293092.3  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293093.3  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293084.2  16.96   0.00 100.00  47.44  59.66   7884  772.326    74   10.893  783.219 unknown GCCause      Allocation Failure  
   293094.3   0.00  18.26   6.23  47.56  59.66   7885  772.442    74   10.893  783.334 unknown GCCause      No GC               
   293094.6   0.00  18.26   6.71  47.56  59.66   7885  772.442    74   10.893  783.334 unknown GCCause      No GC               
   293095.3   0.00  18.26   6.85  47.56  59.66   7885  772.442    74   10.893  783.334 unknown GCCause      No GC               
   293095.6   0.00  18.26   6.92  47.56  59.66   7885  772.442    74   10.893  783.334 unknown GCCause      No GC               
   293096.2   0.00  18.26   9.84  47.56  59.66   7885  772.442    74   10.893  783.334 unknown GCCause      No GC               
   293096.6   0.00  18.26  10.11  47.56  59.66   7885  772.442    74   10.893  783.334 unknown GCCause      No GC 

“分配失败”在其他地方也显示为 GC 原因，但始终作为单个条目。当它以这样的顺序出现时，它与长时间的 GC 暂停相关联。我查看了 Oracle JVM 源代码，“分配失败”看起来很自然：Young 空间不足，无法容纳新数据，是时候清理了。在暂停发生之前，我检查了系统中是否存在任何占用大量内存的意外操作，但没有发现任何可疑之处。

请注意，Young Garbage Collection Time 在暂停时间内不会增加太多。我的内存和GC设置如下（省略日志设置）：

-Xms6000m 
-Xmn2950m 
-Xmx6000m 
-XX:MaxPermSize=192m 
-XX:+UseConcMarkSweepGC 
-XX:+UseParNewGC 
-Dsun.rmi.dgc.client.gcInterval=9223372036854775807 
-Dsun.rmi.dgc.server.gcInterval=9223372036854775807
-XX:CMSInitiatingOccupancyFraction=50 
-XX:+CMSScavengeBeforeRemark 
-XX:+CMSClassUnloadingEnabled

还使用 8000m 和 12000m 堆进行了测试。机器：

• 8 核，16GB 内存
• 24 核，50GB 内存

所以我的基本问题是：为什么 ParNewGC 会偶然出现这种行为？

Answer 1

在执行 GC 之前，它必须让每个线程都到达一个安全点（它不会立即停止每个线程）。如果您有长时间运行的 JNI 调用或系统调用，则可能需要很长时间才能达到安全点。您在这种情况下看到的是长时间的停顿，即使集合本身的时间长度是正常的。