Why are HotSpots compilation log times different to ManagementFactory.getRuntimeMXBean().getUptime()?

Question

When I start the JVM with the argument

-XX:+PrintCompilation

the output is like this:

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

The first column is the time stamp in millisecond, when the log was printed, and I want to compare this time stamp to the value that gets returned by ManagementFactory.getRuntimeMXBean().getUptime():

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

or

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

But my result is like this:

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

It seems that there is about 40 ms difference between them, which makes the two time stamps incomparable. Any ideas how to deal with this?

Cohbath

Which code is writing [62:log... two times? – Elburr

Answer 1

Short Answer

The time printed in the first column of HotSpots JIT compilation logs (when starting the JVM with the "-XX:+PrintCompilation" argument), is of a constant duration greater than the time returned by ManagementFactory.getRuntimeMXBean().getUptime() (given that getUptime is invoked at about the same time as a compilation log gets printed).

This is at least true for JDK 7 running under Windows 7 and can be easily verified by executing the following code with "-XX:+PrintCompilation":

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

The result should look something like this:

 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

Even though ManagementFactory.getRuntimeMXBean().getUptime() was called after the printed JIT compilations, the time returned seems to point to an earlier invocation.

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

Since the time difference is constant and shouldn't change throughout running a JVM, one should still be able to compare the times, as long as one takes the time difference into account.

Long Answer

The "-XX:+PrintCompilation" JVM argument is hardly documented and one can only guess, that the first column represents a time stamp relative to the startup of the JVM. If one has a look at the source code of the HotSpot compiler, it becomes clear though, that the times printed by PrintCompilation and the times returned by ManagementFactory.getRuntimeMXBean().getStartTime() reference two entirely different time stamps that get both initialized during the startup of the JVM.

The compilation logs get printed during calls to 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() is implemented in ostream.cpp and refers to a TimeStamp that gets initialized with the time returned by 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() gets in turn initialized by a call to os::init() during the startup of the JVM:

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

The java method ManagementFactory.getRuntimeMXBean().getStartTime() on the other hand refers to a native method in VMManagementImpl.java:

public native long getStartupTime();

which is implemented in VMManagementImpl.c and returns the time from the JmmInterface constant JMM_JVM_INIT_DONE_TIME_MS:

management.cpp:

  case JMM_JVM_INIT_DONE_TIME_MS:
       return Management::vm_init_done_time();

which gets initialized during the start up of the JVM quite some time after os::init() was already called:

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

Therefore the time printed by JIT compilation logs is different than the time returned by ManagementFactory.getRuntimeMXBean().getStartTime().

Revengeful