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

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

解决方法

简答

在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());
}

结果应如下所示：

06001

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()不同？

解决方法

猜你在找的Java相关文章