java - YGC(ParNew)实时时间远高于user+sys时间

Question

我们有一个在 JBoss 上运行的基于 Web Java 的应用程序，允许的最大堆大小约为 2.2 GB(年轻代为 400MB，总机器物理内存为 4 GB)。在某些时候，应用程序会停止响应(对客户端)几分钟。经过一番分析，我们发现罪魁祸首就是年轻代GC。以下是详细 GC 日志的摘录:

Heap before GC invocations=3844 (full 7):
 par new generation   total 614336K, used 614272K,  eden space 614272K, 100% used,  from space 64K,   0% used,  to   space 64K,   0% used , concurrent mark-sweep generation total 921600K, used 690936K, concurrent-mark-sweep perm gen total 262144K, used 65905K 2679114.965: [GC 2681684.725: [ParNew: 614272K->0K(614336K), 0.0132460 secs] 1305208K->692360K(1535936K), 0.0135020 secs] [Times: user=0.03 sys=0.03, real=2569.62 secs] 
Heap after GC invocations=3845 (full 7):
 par new generation   total 614336K, used 0K,  eden space 614272K,   0% used,  from space 64K,  to   space 64K,   0% used, concurrent mark-sweep generation total 921600K, used 692360K, concurrent-mark-sweep perm gen total 262144K, used 65905K
Total time for which application threads were stopped: 2569.7748610 seconds

我不明白的是，ParNew GC 实际花费的时间大约为 42 分钟(2569 秒)，而 user+sys 时间仅为 0.06 秒，minor 收集的暂停时间仅为 0.06 秒，这怎么可能？ 0.0132460 秒。

我们猜测“虚拟内存抖动”或“高CPU负载”可能会导致此问题，我们测试了两种情况:

1. 我们启动了其他几个程序，这些程序使用了while循环来使用100％的cpu，GC日志如下:6052.217: [GC 6052.217: [ParNew: 409288K->0K(409536K), 1.9456320 秒] 480161K->72140K(1638336K), 1.9460370 秒] [时间: user=0.03 sys=0.00, 实数=1.95秒]

2. 我们启动了其他几个占用大量内存的程序，现在GC日志如下:11710.051:[GC 11710.058:[ParNew:409472K->0K(409536K)，5.9080290秒] 489119K->81136K(1638336K)，5.9256280秒]

在这两种情况下，Young Generation GC 的时间会变长，但 Minor Collection 的暂停时间与实时时间大致相等，似乎没有任何一种情况会导致长时间暂停。

但是其他时间都去哪儿了？

Answer 1

在执行停止世界 GC 之前，所有线程必须到达安全点。通常这种情况发生得很快，但是某些 JNI 方法可能会在没有安全点的情况下运行很长时间。这是 GC 实际启动之前可能出现较长延迟的原因之一。

如果您再次看到此情况，则值得获取 C 级堆栈跟踪(jstack 可能在执行 GC 之前不会响应)