2012-10-26 31 views
16

Tôi đang chạy một số điểm chuẩn vi mô trên mã lặp Java danh sách. Tôi đã sử dụng -XX: + PrintCompilation, và -verbose: gc flags để đảm bảo rằng không có gì đang xảy ra trong nền khi thời gian đang được chạy. Tuy nhiên, tôi thấy một cái gì đó trong đầu ra mà tôi không thể hiểu được.Hiểu đầu ra của -XX: + PrintCompilation

Dưới đây là đoạn mã, tôi chạy benchmark trên:

import java.util.ArrayList; 
import java.util.List; 

public class PerformantIteration { 

    private static int theSum = 0; 

    public static void main(String[] args) { 
     System.out.println("Starting microbenchmark on iterating over collections with a call to size() in each iteration"); 
     List<Integer> nums = new ArrayList<Integer>(); 
     for(int i=0; i<50000; i++) { 
      nums.add(i); 
     } 

     System.out.println("Warming up ..."); 
     //warmup... make sure all JIT comliling is done before the actual benchmarking starts 
     for(int i=0; i<10; i++) { 
      iterateWithConstantSize(nums); 
      iterateWithDynamicSize(nums); 
     } 

     //actual   
     System.out.println("Starting the actual test"); 
     long constantSizeBenchmark = iterateWithConstantSize(nums); 
     long dynamicSizeBenchmark = iterateWithDynamicSize(nums); 
     System.out.println("Test completed... printing results"); 

     System.out.println("constantSizeBenchmark : " + constantSizeBenchmark); 
     System.out.println("dynamicSizeBenchmark : " + dynamicSizeBenchmark); 
     System.out.println("dynamicSizeBenchmark/constantSizeBenchmark : " + ((double)dynamicSizeBenchmark/(double)constantSizeBenchmark)); 
    } 

    private static long iterateWithDynamicSize(List<Integer> nums) { 
     int sum=0; 
     long start = System.nanoTime();   
     for(int i=0; i<nums.size(); i++) { 
      // appear to do something useful 
      sum += nums.get(i); 
     }  
     long end = System.nanoTime(); 
     setSum(sum); 
     return end-start; 
    } 

    private static long iterateWithConstantSize(List<Integer> nums) { 
     int count = nums.size(); 
     int sum=0; 
     long start = System.nanoTime();   
     for(int i=0; i<count; i++) { 
      // appear to do something useful 
      sum += nums.get(i); 
     } 
     long end = System.nanoTime(); 
     setSum(sum); 
     return end-start; 
    } 

    // invocations to this method simply exist to fool the VM into thinking that we are doing something useful in the loop 
    private static void setSum(int sum) { 
     theSum = sum;  
    } 

} 


Dưới đây là đầu ra.

152 1  java.lang.String::charAt (33 bytes) 
    160 2  java.lang.String::indexOf (151 bytes) 
    165 3Starting microbenchmark on iterating over collections with a call to size() in each iteration  java.lang.String::hashCode (60 bytes) 
    171 4  sun.nio.cs.UTF_8$Encoder::encodeArrayLoop (490 bytes) 
    183 5 
     java.lang.String::lastIndexOf (156 bytes) 
    197 6  java.io.UnixFileSystem::normalize (75 bytes) 
    200 7  java.lang.Object::<init> (1 bytes) 
    205 8  java.lang.Number::<init> (5 bytes) 
    206 9  java.lang.Integer::<init> (10 bytes) 
    211 10  java.util.ArrayList::add (29 bytes) 
    211 11  java.util.ArrayList::ensureCapacity (58 bytes) 
    217 12  java.lang.Integer::valueOf (35 bytes) 
    221 1%  performance.api.PerformantIteration::main @ 21 (173 bytes) 
Warming up ... 
    252 13  java.util.ArrayList::get (11 bytes) 
    252 14  java.util.ArrayList::rangeCheck (22 bytes) 
    253 15  java.util.ArrayList::elementData (7 bytes) 
    260 2%  performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes) 
    268 3%  performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes) 
    272 16  performance.api.PerformantIteration::iterateWithConstantSize (59 bytes) 
    278 17  performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes) 
Starting the actual test 
Test completed... printing results 
constantSizeBenchmark : 301688 
dynamicSizeBenchmark : 782602 
dynamicSizeBenchmark/constantSizeBenchmark : 2.5940773249184588 


Tôi không hiểu bốn dòng từ đầu ra.

260 2%  performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes) 
268 3%  performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes) 
272 16  performance.api.PerformantIteration::iterateWithConstantSize (59 bytes) 
278 17  performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes) 


  • Tại sao cả hai phương pháp được biên soạn hai lần?
  • Làm cách nào để đọc đầu ra này ... các số khác nhau có ý nghĩa gì?
+0

Cảm ơn @Thomas Jungblut Không chắc thế nào tôi bỏ lỡ -XX: + PrintCompilation từ tiêu đề – Parag

+2

np, đây là tài nguyên tốt về các bộ sưu tập: https://gist.github.com/1165804#file_notes.md –

Trả lời

15

Tôi sẽ cố gắng trả lời câu hỏi của riêng mình với sự trợ giúp của số link này được đăng bởi Thomas Jungblut.

260 2%  performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes) 
268 3%  performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes) 
272 16  performance.api.PerformantIteration::iterateWithConstantSize (59 bytes) 
278 17  performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes) 

Cột đầu tiên

Cột đầu tiên '260' là dấu thời gian.

cột thứ hai

Cột thứ hai là compilation_id và method_attributes. Khi một trình biên dịch HotSpot được kích hoạt, mọi đơn vị biên dịch sẽ nhận được một id biên dịch. Số trong cột thứ hai là id biên dịch. Biên dịch JIT, và trình biên dịch OSR có hai trình tự khác nhau cho id biên dịch. Vì vậy 1% và 1 là các đơn vị biên dịch khác nhau. % Trong hai hàng đầu tiên, tham khảo thực tế rằng đây là một trình biên dịch OSR. Một trình biên dịch OSR đã được kích hoạt vì mã đã được lặp qua một vòng lặp lớn và VM xác định rằng mã này là nóng. Vì vậy, một trình biên dịch OSR đã được kích hoạt, điều này sẽ cho phép máy ảo thực hiện On Stack Replacement và chuyển sang mã được tối ưu hóa, khi nó đã sẵn sàng.

Thứ ba cột

Cột thứ ba performance.api.PerformantIteration::iterateWithConstantSize là tên phương pháp.

cột thứ tư

Cột thứ tư là một lần nữa khác nhau khi OSR biên soạn xảy ra và khi nó không. Hãy xem xét các phần phổ biến trước. Phần cuối của cột thứ tư (59 byte), đề cập đến kích thước của đơn vị biên dịch trong bytecode (không phải kích thước của mã được biên dịch). Phần 19 trong quá trình biên dịch OSR đề cập đến osr_bci.Tôi sẽ trích dẫn từ liên kết nêu trên -

A "chỗ" trong một phương pháp Java được xác định bởi chỉ số của nó bytecode (BCI), và nơi mà gây ra một biên soạn OSR được gọi là "osr_bci" . Một nmethod biên dịch OSR chỉ có thể được nhập từ osr_bci của nó; có có thể là nhiều phiên bản được biên dịch OSR của cùng một phương pháp tại cùng một thời điểm , miễn là osr_bci của chúng khác nhau.

Cuối cùng, tại sao phương pháp được biên dịch hai lần?

Đầu tiên là trình biên dịch OSR, có lẽ đã xảy ra trong khi vòng lặp đang chạy do mã khởi động (trong ví dụ), và biên dịch thứ hai là biên dịch JIT, có lẽ để tối ưu hóa hơn nữa mã đã biên dịch?

+0

nếu bạn nhận được mã OSR trong khi khởi động "bạn đang làm sai". Cũng liệt kê các đối số của JVM, nó có thể chỉ là C1 (trình biên dịch client/dumb) và C2 (trình biên dịch thông minh, chậm hơn). Việc biên dịch lại có thể là kết quả của quá trình khử sắc tố. Cách dễ nhất (?) Là liệt kê mã được tạo ra, nếu bạn thấy cuống C1, bạn biết đó là mã C1. – bestsss

+0

@bestsss Tại sao vậy? Tôi nghĩ rằng trình biên dịch OSR đang xảy ra vì mã khởi động của ví dụ gọi một vòng lặp lớn. – Parag

+0

Quan điểm của tôi là nếu bạn cố gắng làm ấm bất cứ điều gì, bạn nên tránh OSR, chia nhỏ nó bằng các phương pháp nhỏ hơn. – bestsss

-1

Tôi nghĩ rằng lần đầu tiên OSR đã xảy ra, sau đó nó thay đổi phương pháp tigger Invocation Counter compilar (PS: xin lỗi, tiếng anh của tôi là hồ bơi)

Các vấn đề liên quan