java - PrintGCApplicationStoppedTime 报告的 "stop the world"时间真的准确吗？

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|  DurationDATA|1330360259830|            230|1330360260139|            7|       309DATA|1330360259849|            211|1330360260138|            8|       289DATA|1330360259960|            100|1330360260135|           11|       175DATA|1330360259979|             81|1330360260135|           11|       156DATA|1330360259980|             80|1330360260135|           11|       155DATA|1330360259989|             71|1330360260135|           11|       146DATA|1330360260019|             41|1330360260135|           11|       116DATA|1330360260029|             31|1330360260135|           11|       106  GC|1330360260060|              0|1330360260146|            0|        86

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

openjdk 的 hotspot/src/share/vm/runtime/safepoint.cpp 中的方法 SafepointSynchronize::end() 中的代码似乎唤醒了挂起的 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

这些标志的命名不正确，您认为它们不可靠是对的。您要查找的错误报告是 this one它在 hs17 中得到修复，它首先在 6u21 中投入生产(根据 this fix list )所以你的版本太旧了。

另请注意，无论如何您都在错误地使用数据。 stoppedtime 标志伴随着 PrintGCApplicationConcurrentTime 标志，这两个标志打印的是在安全点花费的时间，您可以使用 PrintSafepointStatistics 了解安全点的用途。

This answer是一个类似的主题。