java - jHiccup 分析没有加起来

Question

我有以下 jHiccup 结果。

显然图中有几秒的巨大峰值。我的应用程序每 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停顿时间。

Answer 1

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

jHiccup 观察到 JVM 上运行的应用程序线程也会看到的“打嗝”。它不收集原因 - 只报告事实。原因可以是任何会导致进程无法完美运行准备运行代码的原因:GC 暂停是一个常见原因，但键盘上的临时 ^Z 或虚拟主机之间的“实时迁移”之一是也观察到了……有很多可能的原因，包括操作系统或管理程序级别(如果存在)的调度压力、电源管理疯狂、交换和许多其他原因。我已经看到 Linux 文件系统压力和 Transparent Huge Page“后台”碎片整理也会导致多秒的问题...

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

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

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

这可能不是 GC，但在您排除 GC 之前，我建议您多研究一下 GC 日志记录。首先，将暂停限制为 200 毫秒的 JVM 提示在所有已知的 JVM 上都是无用的。暂停提示相当于说“请”。此外，不要相信您的 GC 日志，除非您在选项中包含 -XX:+PrintGCApplicationStoppedTime(甚至怀疑它们)。有一些暂停和部分暂停可能会很长并且不会被报告，除非您包括此标志。例如。我已经看到偶尔长时间运行的计数循环导致暂停需要 15 秒才能到达安全点，其中 GC 仅报告它实际完成一些工作的暂停的 .08 秒部分。还有许多暂停的原因不被视为“GC”的一部分，因此可能不会被 GC 日志记录标志报告。

——吉尔。 [jHiccup 的作者]