Java – why do hotspots compile logs at the same time as managementfactory getRuntimeMXBean(). Getuptime() is different?

When I start the JVM with parameters

-XX:+PrintCompilation

The output is as follows:

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

The first column is the timestamp in milliseconds. When printing the log, I want to compare this timestamp with managementfactory Compare the value returned by getruntimemxbean() getUptime()：

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

or

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

But my result is this:

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

It seems that there is a difference of about 40 milliseconds between them, which makes the two timestamps incomparable Any idea how to deal with this?

Solution

Brief answer

The duration of the time printed in the first column of the hotspots JIT compilation log (when starting the JVM with the "- XX: printcompilation" parameter) is greater than that of managementfactory The time returned by getruntimemxbean() Getuptime() (call getuptime at about the same time when the compilation log is printed)

For JDK 7 running under Windows 7, this is at least correct and can be easily verified by executing the following code using "- XX: printcompilation":

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

The results shall be as follows:

06001

JVM uptime: 43

Even after the compiled JIT is compiled, ManagementFactory. is called. getRuntimeMXBean(). Getuptime(), the return time also seems to point to the earlier call

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 should not change when running the JVM, it should still be possible to compare time as long as the time difference is considered

The answer is long

The "- XX: printcompilation" JVM parameter has almost no record, so you can only guess that the first column represents the timestamp relative to the JVM startup If you look at the source code of the hotspot compiler, it is obvious that the printing time of printcompilation is the same as that of managementfactory The time returned by getruntimemxbean() Getstarttime () refers to two completely different timestamps, both of which are at the start of the JVM

When calling compiletask:: Print_ compilation_ Print compilation log during 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() in ostream CPP and references a timestamp, which uses OS:: elapsed_ Initialize at the time returned by 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() is initialized by calling OS:: init() during startup of the JVM:

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

On the other hand, the Java method managementfactory getRuntimeMXBean(). Getstarttime() refers to vmmanagementimpl Native methods in Java:

public native long getStartupTime();

It is in vmmanagementimpl C, and from the jmminterface constant JMM_ JVM_ INIT_ DONE_ TIME_ MS return time:

management. cpp：

case JMM_JVM_INIT_DONE_TIME_MS:
       return Management::vm_init_done_time();

For some time after calling OS:: init(), it is initialized during JVM startup:

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

Therefore, the time of JIT compilation log printing is the same as that of managementfactory getRuntimeMXBean(). The time returned by getstarttime() is different