用PrintGCApplicationStoppedTime报道的"停止世界"时间真的准确吗？

Question

我试图通过使用-XX:+ PrintGCApplicationStoppedTime JVM选项来估计垃圾收集"停止世界"暂停时Java应用程序中的线程被阻止了多长时间.

我解析gc.log文件并将报告的停止时间添加到GC时间戳(-XX:+ PrintGCDateStamps)以获取GC事件的"开始和停止"时间戳.

应用程序线程测量发送HTTP请求并获取响应所需的时间,并在发送请求时记录时间戳以及请求的持续时间.

当我将GC事件时间戳与应用程序(DATA)时间戳进行比较时,我得到一些奇怪的结果:

Type|   Start time|Start time diff|     End time|End time diff|  Duration
DATA|1330360259830|            230|1330360260139|            7|       309
DATA|1330360259849|            211|1330360260138|            8|       289
DATA|1330360259960|            100|1330360260135|           11|       175
DATA|1330360259979|             81|1330360260135|           11|       156
DATA|1330360259980|             80|1330360260135|           11|       155
DATA|1330360259989|             71|1330360260135|           11|       146
DATA|1330360260019|             41|1330360260135|           11|       116
DATA|1330360260029|             31|1330360260135|           11|       106
  GC|1330360260060|              0|1330360260146|            0|        86

上面的"奇数"部分是大多数"DATA"条目在GC事件结束前11毫秒结束.我的解释是,从应用程序线程从安全点"释放"到GC计算"停止世界"时间大约需要11毫秒.
这种解释是否正确？

openjdk 中方法SafepointSynchronize::end()中的代码hotspot/src/share/vm/runtime/safepoint.cpp似乎在计算停止时间之前唤醒挂起的java线程.
这意味着报告的停止时间不可靠,计算停止时间的线程可能会在唤醒java线程和计算时间之间暂停,对吗？
(我不是C++程序员,所以我可能误解了代码.)

该应用程序在Solaris 10 5/08 x86服务器上与Oracle JDK 1.6.0_20一起运行.

命令行:

java -Xss128k -Xms1024m -Xmx1024m -XX:MaxPermSize=28m -Xloggc:logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintHeapAtGC -classpath [...] net.grinder.engine.process.WorkerProcessEntryPoint

Answer 1

这些标志名称不正确,你说它们是不正确的.您之前的错误报告就是这个,并且它已在hs17中修复,它首次在6u21中生成(根据此修复列表),因此您的版本太旧了.

另请注意,您仍然无法正确使用数据.停止时间标志伴随着一个PrintGCApplicationConcurrentTime标志,这两个标志正在打印的是安全点所花费的时间,您可以使用PrintSafepointStatistics有关安全点的信息.

这个答案是关于类似的主题.