什么会导致次要 GC 时间和总暂停时间之间存在很大差异？

Question

我们有一个对延迟敏感的应用程序，并且遇到了一些我们不完全理解的与 GC 相关的暂停。我们偶尔会遇到次要 GC，导致应用程序暂停时间比报告的 GC 时间本身长得多。这是一个示例日志 sn-p：

485377.257: [GC 485378.857: [ParNew: 105845K->621K(118016K), 0.0028070 secs] 136492K->31374K(1035520K), 0.0028720 secs] [Times: user=0.01 secs] [Times: user=0.01 secs] , 实数=1.61 秒]
应用程序线程停止的总时间：1.6032830 秒

这里的总暂停时间比报告的 GC 时间长几个数量级。这些是孤立的偶发事件：之前和之后的次要 GC 事件并没有显示出如此大的差异。

该进程在专用机器上运行，具有大量可用内存、8 个内核，运行内核为 2.6.9-89.0.1EL-smp 的 Red Hat Enterprise Linux ES Release 4 Update 8。我们在（32 位）JVM 版本 1.6.0_13 和 1.6.0_18 中观察到了这一点。

我们正在使用这些标志运行：

-server -ea -Xms512m -Xmx512m -XX:+UseConcMarkSweepGC -XX:NewSize=128m -XX:MaxNewSize=128m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:-TraceClassUnloading

任何人都可以就这里可能发生的情况和/或进一步调查的一些途径提供一些解释吗？

Answer 1

你确定你没有交换？通常看到：

时间：user=0.01 sys=0.00, real=1.61 secs

（来自你的踪迹）

表明进程中发生了一些不占用 CPU 但确实占用挂钟时间的事情……通常是交换或其他 I/O。一点 iostat 可能有助于阐明...

您是否在 Java 堆外使用了大量本机内存？ （可能通过 DirectByteBuffer、nio 等。）这可能会影响您的“大量可用内存”声明（令您惊讶的是）。 'top' 或 vmstat 也可能显示此内容。

Answer 2

“安全点时间”是这类事情的一个广泛原因。不幸的是，GC 只记录从开始工作（在所有应用程序线程都已在安全点暂停之后）到完成（之后线程将从其安全点释放）的时间。 -XX:+PrintGCApplicationStoppedTime（更正确）报告从告诉第一个线程进入安全点到最后一个线程被释放以再次运行的时间。

不幸的是，看到一个线程需要很长时间才能到达安全点是很常见的，当这种情况发生时，所有其他友好而礼貌的线程会在被告知时等待到安全点并暂停在那里进来。这种事情的例子是长时间的运行时操作。例如。在大多数 JVM 中，克隆对象数组是在没有内部安全点机会的情况下完成的（想象克隆一个 1GB 的数组，并且恰好需要在中间进行 GC 暂停）。在没有内部安全点的情况下，您自己的优化计数循环也可能最终运行很长时间。

[Zing 有一个内置的安全点时间分析器，部分是为了跟踪和击败这类事情]。

Answer 3

您说有“大量可用内存”，但您的堆大小上限为 512MB。您可能比您想象的更频繁/更早地耗尽内存。