我试图通过使用-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 …