Tại sao thời gian ghi nhật ký của HotSpots khác với ManagementFactory.getRuntimeMXBean(). GetUptime()?

Question

Khi tôi bắt đầu JVM với lập luận

-XX:+PrintCompilation 

đầu ra là như thế này:

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

Cột đầu tiên là dấu thời gian trong phần nghìn giây, khi các bản ghi đã được in, và tôi muốn so sánh tem thời gian này để giá trị đó được trả về bởi ManagementFactory.getRuntimeMXBean().getUptime():

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

hoặc

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

Nhưng kết quả của tôi là như thế này:

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

Có vẻ như rằng có khoảng 40 ms khác biệt giữa chúng, mà làm cho hai tem thời gian không thể so sánh. Bất kỳ ý tưởng làm thế nào để đối phó với điều này?

Answer 1

ngắn trả lời

Thời gian in trong cột đầu tiên của bản ghi biên soạn hotspots JIT (khi khởi động JVM với "-XX: + PrintCompilation" lập luận), là một thời gian liên tục lớn hơn thời gian được trả về bởi ManagementFactory.getRuntimeMXBean(). getUptime() (cho rằng getUptime được gọi vào khoảng thời gian giống như một bản ghi biên soạn được in).

Đây là ít nhất đúng đối với JDK 7 chạy hệ điều hành Windows 7 và có thể dễ dàng kiểm tra bằng cách thực hiện đoạn mã sau với "-XX: + PrintCompilation":

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

Kết quả sẽ giống như thế này: thời gian hoạt động

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

E mặc dù ManagementFactory.getRuntimeMXBean(). getUptime() được gọi sau khi biên dịch JIT được in, thời gian trả về dường như trỏ đến một lời gọi trước đó.

Dường như chúng có chênh lệch khoảng 40 ms, sự khác biệt này khiến nó không thể so sánh được. Bất kỳ ý tưởng làm thế nào để đối phó với điều này?

Vì chênh lệch thời gian không thay đổi và không được thay đổi trong suốt quá trình chạy JVM, bạn vẫn có thể so sánh thời gian, miễn là có thời gian khác nhau.

dài trả lời

Các "-XX: + PrintCompilation" lập luận JVM là hầu như không ghi nhận và người duy nhất có thể đoán, rằng cột đầu tiên đại diện cho một tem thời gian tương đối so với khởi động của JVM. Nếu có một cái nhìn vào mã nguồn của trình biên dịch HotSpot, nó trở nên rõ ràng, mặc dù thời gian được in bởi PrintCompilation và thời gian được trả về bởi ManagementFactory.getRuntimeMXBean(). GetStartTime() tham chiếu đến hai tem thời gian hoàn toàn khác nhau được khởi tạo trong suốt sự khởi động của JVM.

Các bản ghi biên soạn được in trong các cuộc gọi đến 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() được thực hiện trong ostream.cpp và đề cập đến một TimeStamp đó được khởi tạo với thời gian trả về bởi 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() được lần lượt khởi tạo bởi một cuộc gọi đến os :: init() trong startup of the JVM:

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

Phương pháp java ManagementFactory.getRuntimeMXBean() getStartTime(). Mặt khác đề cập đến một phương pháp có nguồn gốc trong VMManagementImpl.java:

public native long getStartupTime(); 

được thực hiện trong VMManagementImpl.c và trả về thời gian từ JmmInterface liên tục JMM _JVM_INIT_DONE_TIME_MS:

management.cpp:

case JMM_JVM_INIT_DONE_TIME_MS: 
     return Management::vm_init_done_time(); 

mà được khởi tạo trong khởi động của JVM khá một thời gian sau khi os :: init() đã được gọi là:

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

Do đó thời gian in bởi các bản ghi biên dịch JIT khác với thời gian được trả về bởi ManagementFactory.getRuntimeMXBean(). getStartTime().