当我用参数启动 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]

看起来它们之间大约有40ms的差异，这使得两个时间戳没有可比性。任何想法如何处理这个？

最佳答案

简答题

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 uptime: 43

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

It seems that they have a around 40 ms difference, this difference makes it incomparable. Any ideas how to deal with this?

由于时差是恒定的，并且在运行 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用 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 中的本地方法。 :

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()返回的时间是不一样的。

关于java - 为什么 HotSpots 编译日志时间与 ManagementFactory.getRuntimeMXBean().getUptime() 不同？，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/13538555/