为什么 HotSpots 编译日志时间与 ManagementFactory.getRuntimeMXBean().getUptime() 不同？答案

【问题标题】：Why are HotSpots compilation log times different to ManagementFactory.getRuntimeMXBean().getUptime()?为什么 HotSpots 编译日志时间与 ManagementFactory.getRuntimeMXBean().getUptime() 不同？
【发布时间】：2012-11-12 09:03:58
【问题描述】：

当我使用参数启动 JVM 时

-XX:+PrintCompilation

输出是这样的：

 60    1             java.lang.String::hashCode (55 bytes)
 74    2             sun.nio.cs.UTF_8$Encoder::encode (361 bytes)

第一列是以毫秒为单位的时间戳，当打印日志时，我想将此时间戳与ManagementFactory.getRuntimeMXBean().getUptime()返回的值进行比较：

long jvmUpTime = ManagementFactory.getRuntimeMXBean().getUptime();

或

long jvmStartTime = ManagementFactory.getRuntimeMXBean().getStartTime();

但我的结果是这样的：

[62:log from Java code]
103    5             benchmark.AbstractBenchmarkST::benchmark (82 bytes)
[62:log from Java code]

似乎它们之间有大约40毫秒的差异，这使得两个时间戳无法比拟。任何想法如何处理这个？

【问题讨论】：

哪个代码写[62:log...两次？

标签： java jvm benchmarking jvm-hotspot

【解决方案1】：

简答

HotSpots JIT 编译日志第一列中打印的时间（使用“-XX:+PrintCompilation”参数启动 JVM 时）的持续时间大于 ManagementFactory.getRuntimeMXBean().getUptime 返回的时间()（假设 getUptime 在编译日志打印的同时被调用）。

这对于在 Windows 7 下运行的 JDK 7 来说至少是正确的，并且可以通过使用“-XX:+PrintCompilation”执行以下代码来轻松验证：

public static void main(String[] args) {
    System.out.println("JVM uptime: " + ManagementFactory.getRuntimeMXBean().getUptime());
}

结果应该是这样的：

 77    1             java.lang.String::hashCode (55 bytes)
 79    2             java.lang.String::indexOf (70 bytes)
 80    3             java.lang.String::charAt (29 bytes)
 82    4             java.lang.String::lastIndexOf (52 bytes)
 82    5             java.lang.String::equals (81 bytes)
 82    6             java.lang.AbstractStringBuilder::ensureCapacityInternal (16 bytes)
 82    7             java.lang.String::indexOf (166 bytes)
 85    8     n       java.lang.System::arraycopy (native)   (static)

JVM 正常运行时间：43

即使在打印的 JIT 编译之后调用了 ManagementFactory.getRuntimeMXBean().getUptime()，返回的时间似乎指向更早的调用。

似乎他们有大约 40 毫秒的差异，这个差异使它无法比拟。任何想法如何处理这个？

由于时间差是恒定的，并且在整个运行 JVM 过程中不应该改变，所以只要考虑时间差，应该仍然可以比较时间。

长答案

“-XX:+PrintCompilation”JVM 参数几乎没有文档记录，只能猜测，第一列表示相对于 JVM 启动的时间戳。如果看一下 HotSpot 编译器的源代码，就会很清楚，PrintCompilation 打印的时间和 ManagementFactory.getRuntimeMXBean().getStartTime() 返回的时间引用了两个完全不同的时间戳，它们都在期间初始化JVM的启动。

在调用CompileTask::print_compilation_impl时会打印编译日志：

void CompileTask::print_compilation_impl(outputStream* st, Method* method, int compile_id, int comp_level,
                                        bool is_osr_method, int osr_bci, bool is_blocking,
                                        const char* msg, bool short_form) {
    if (!short_form) {
        st->print("%7d ", (int) st->time_stamp().milliseconds());  // print timestamp
    }
    st->print("%4d ", compile_id);    // print compilation number
    [...]
}

st->time_stamp() 在 ostream.cpp 中实现，并引用 TimeStamp，该 TimeStamp 使用 os::elapsed_counter() 返回的时间进行初始化：

ostream.cpp:

 void outputStream::stamp() {
     if (! _stamp.is_updated()) {
         _stamp.update(); // start at 0 on first call to stamp()
     }
     [...]
 }

timer.cpp:

 void TimeStamp::update() {
     update_to(os::elapsed_counter());
 }

os::elapsed_counter() 在startup of the JVM: 期间通过调用 os::init() 依次被初始化：

jint Threads::create_vm(JavaVMInitArgs* args, bool* canTryAgain) {
    [...]
    os::init();
    [...]
}

另一方面，java方法ManagementFactory.getRuntimeMXBean().getStartTime()引用VMManagementImpl.java中的native方法：

public native long getStartupTime();

在VMManagementImpl.c中实现，从JmmInterface常量JMM_JVM_INIT_DONE_TIME_MS中返回时间：

management.cpp:

  case JMM_JVM_INIT_DONE_TIME_MS:
       return Management::vm_init_done_time();

在 os::init() 被调用后的一段时间内，它在 JVM 启动期间被初始化：

jint Threads::create_vm(JavaVMInitArgs* args, bool* canTryAgain) {
    [...]
    os::init();
    [...]
    // record VM initialization completion time
    Management::record_vm_init_completed();
    [...]
}

因此JIT编译日志打印的时间与ManagementFactory.getRuntimeMXBean().getStartTime()返回的时间不同。

【讨论】：