10

我有以下 jHiccup 结果。

j打嗝分析图

显然，图中有几秒的巨大峰值。我的应用每 100 毫秒左右输出一次日志。当我阅读我的日志时，我从未见过如此巨大的停顿。我还可以通过 JVM 诊断检查在 GC 中花费的总时间，它显示以下内容：

Time: 
2013-03-12 01:09:04
Used: 
 1,465,483 kbytes
Committed: 
 2,080,128 kbytes
Max: 
 2,080,128 kbytes
GC time: 
     2 minutes on ParNew (4,329 collections)

8.212 seconds on ConcurrentMarkSweep (72 collections)

big-GC 的总时间约为 8 秒，分布在 72 个单独的集合中。根据我的 JVM 提示，所有这些都低于 200 毫秒以限制暂停。

另一方面，我在我的独立网络日志（wireshark）中恰好观察到一个网络响应时间为 5 秒的实例。这意味着存在暂停，但它们不是 GC，它们不是阻塞线程或可以在分析器或线程转储中观察到的东西。

我的问题是调试或调整此行为的最佳方法是什么？

此外，我想了解 jHiccup 是如何进行测量的。显然这不是 GC 暂停时间。

4

1 回答 1

28

很高兴看到您正在使用 jHiccup，并且它似乎显示了基于现实的打嗝。

jHiccup 观察到运行在 JVM 上的应用程序线程也会看到的“打嗝”。它没有收集原因 - 只是报告事实。原因可能是任何会导致进程无法运行完全准备好运行的代码的原因：GC 暂停是常见原因，但键盘上的临时 ^Z 或跨虚拟主机的“实时迁移”事件之一将是也观察到了.. 有多种可能的原因，包括操作系统或管理程序级别的调度压力（如果存在）、电源管理的疯狂、交换以及许多其他原因。我已经看到 Linux 文件系统压力和透明大页面“背景”碎片整理也会导致多秒的打嗝......

隔离暂停原因的第一步是使用 jHiccup 中的“-c”选项：它启动一个单独的控制进程（具有其他空闲工作负载）。如果您的应用程序和控制进程都显示大小和时间大致相关的打嗝，您就会知道您正在寻找系统级别（而不是进程本地）的原因。如果它们不相关，你就会怀疑你的 JVM 内部——这很可能表明你的 JVM 暂停了一些大事；GC 或其他东西，如锁去偏或类加载派生去优化，如果由于某种原因到达安全点的时间很长（并且在大多数 JVM，有很多可能的原因导致很长一段时间到达安全点）。

jHiccup 的测量非常简单，很难出错。整个东西不到650行java代码，大家可以自己看逻辑。jHiccup 的 HiccupRecorder 线程反复休眠 1 毫秒，当它醒来时，它会记录任何大于 1 毫秒的时间差（从休眠前开始）作为打嗝。一个简单的假设是，如果一个准备运行的线程（HiccupRecorder）没有运行 5 秒，同一进程中的其他线程也会看到类似大小的打嗝。

正如您在上面提到的，jHiccups 观察结果似乎在您的独立网络日志中得到证实，您在其中看到了 5 秒的响应时间，请注意，网络日志不会观察到所有的打嗝，因为只有在打嗝期间实际发出的请求才会有被网络记录器观察到。相比之下，没有大于 ~1 毫秒的打嗝可以隐藏 jHiccup，因为即使没有其他活动，它也会每秒尝试唤醒 1,000 次。

这可能不是 GC，但在您排除 GC 之前，我建议您多查看 GC 日志记录。首先，将暂停时间限制为 200 毫秒的 JVM 提示在所有已知的 JVM 上都是无用的。暂停提示相当于说“请”。此外，不要相信您的 GC 日志，除非您在选项中包含 -XX:+PrintGCApplicationStoppedTime （并且即使在那时也怀疑它们）。除非您包含此标志，否则有些停顿和部分停顿可能会很长并且未报告。例如，我看到偶尔长时间运行的计数循环需要 15 秒才能达到安全点而导致的暂停，其中 GC 仅报告暂停的 0.08 秒部分，它实际上做了一些工作。还有很多暂停的原因不被认为是“GC”的一部分

——吉尔。[jHiccup的作者]

于 2013-03-12T03:33:07.233 回答