jHiccup分析没有加起来

我有以下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) 

72个独立系列的总大GC时间约为8秒。 根据我的JVM提示，所有这些都低于200毫秒，以限制暂停。

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

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

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

Answer 1

很高兴看到你正在使用jHiccup，它似乎表现出基于现实的打嗝。

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

隔离暂停原因的第一步是在jHiccup中使用“-c”选项：它启动一个单独的控制进程（否则是空闲的工作负载）。 如果您的应用程序和控制过程都显示大小和时间大致相关的打嗝，您就会知道您正在寻找系统级（而不是过程本地）的原因。 如果它们没有关联，你就会知道你的JVM的内部 – 这很可能表明你的JVM暂停了一些大事; 无论是GC还是别的东西，比如锁定debiasing或类加载 – 派生 – 去优化，如果由于某种原因，时间到安全点很长，那么在某些JVM上可能会花费很长时间[并且通常在日志中没有报告]时间（以及大多数JVM，有很多可能的原因导致长时间安全点。

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

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

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

– 吉尔 [jHiccup的作者]