7

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

4

1 回答 1

0

简答

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，它使用 os::elapsed_counter() 返回的时间进行初始化：

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

于 2014-02-09T14:41:09.153 回答