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

Question

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

485377.257: [GC 485378.857: [ParNew: 105845K->621K(118016K), 0.0028070 secs] 136492K->31374K(1035520K), 0.0028720 secs] [Times: user=0.01 sys=0.00, real=1.61 secs]
Total time for which application threads were stopped: 1.6032830 seconds

这里的总暂停时间比报告的 GC 时间长几个数量级。这些是孤立且偶然发生的事件:之前和之后的次要 GC 事件不会显示出这种大的差异。

该进程在一台专用机器上运行，有大量可用内存，8 个内核，运行 Red Hat Enterprise Linux ES Release 4 Update 8，内核为 2.6.9-89.0.1EL-smp。我们在(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

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

时间:用户=0.01 系统=0.00，真实=1.61 秒

(来自你的踪迹)

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

您是否在 Java 堆之外使用了大量 native 内存？ (可能通过 DirectByteBuffer、nio 等)这可能会侵 eclipse 您的“大量可用内存”声明(令您大吃一惊)。 'top' 或 vmstat 也可能会显示此内容。