java – 用PrintGCApplicationStoppedTime报告的“停止世界”时

我解析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的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