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

Question

当我用参数启动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毫秒的差异,这使得两个时间戳无法比拟.任何想法如何处理这个？

Answer 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

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

看起来他们有大约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 中实现，并引用使用 os::elapsed_counter() 返回的时间初始化的TimeStamp ：

ostream.cpp：

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

定时器.cpp：

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

os::elapsed_counter() 在JVM 启动期间通过调用 os::init() 依次初始化：

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

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

public native long getStartupTime();

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

管理.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() 返回的时间不同。