2013-03-11 59 views
8

我有以下jHiccup结果。jHiccup分析不加起来

jHiccup analysis graph

显然,有图中的一些秒的巨大峰值。我的应用每隔100 ms左右输出一次日志。当我阅读我的日志时,我从未看到如此巨大的停顿。我还可以检查从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) 

总大-GC时间约为8秒遍布72个分开收集。所有这些都是根据我的JVM提示低于200ms来限制暂停。

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

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

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

回答

24

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

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

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

jHiccup的测量非常简单,以至于很难弄错。整个事情少于650行的Java代码,所以你可以看看自己的逻辑。 jHiccup的HiccupRecorder线程重复进入睡眠1毫秒,当它醒来时,它会记录任何时间(从睡眠之前)的差异,即大于1毫秒的呃逆。简单的假设是,如果一个准备运行的线程(HiccupRecorder)不能运行5秒钟,同一进程中的其他线程也会看到类似大小的呃逆。

如上所述,jHiccups观察似乎在独立网络日志中得到证实,您看到5秒的响应时间。请注意,并非所有的打嗝都会被网络日志观察到,因为只有实际进行的请求网络记录器会观察到打嗝。相比之下,没有大于1毫秒的呃逆可以躲避jHiccup,因为即使没有其他活动,它也会每秒唤醒1,000次。

可能不是GC,但在你排除GC之前,我建议你看看GC日志记录多一点。首先,JVM提示将暂停时间限制为200毫秒对所有已知的JVM都没有用处。暂停暗示相当于说“请”。另外,除非在选项中包含-XX:+ PrintGCApplicationStoppedTime(并且即使那样可疑),也不要相信GC日志。除非包含此标志,否则可能会有很长时间的暂停和部分暂停并未报告。例如。我看到偶尔长时间运行的计数循环需要15秒才能达到安全点,因为GC只报告了实际做了一些工作的暂停时间的.08秒部分所引起的暂停。还有很多暂停,其原因不被认为是“GC”的一部分,因此可能未被GC日志标记报告。

- Gil。 [jHiccup的作者]