java - Entendiendo la salida de-XX:+PrintCompilation

microbenchmark

Question

Estoy ejecutando algunos micro benchmarks en el código de iteración de lista de Java. He utilizado los indicadores -XX: + PrintCompilation y -verbose: gc para garantizar que no ocurra nada en segundo plano cuando se está ejecutando el tiempo. Sin embargo, veo algo en la salida que no puedo entender.

Aquí está el código, estoy ejecutando el punto de referencia en:

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;       
    }

}

Aquí está la salida.

    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

No entiendo estas cuatro líneas de la salida.

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)

• ¿Por qué estos dos métodos se compilan dos veces?
• ¿Cómo leo esta salida ... qué significan los distintos números?

Answer 1

Creo que la primera vez que sucedió OSR, luego se modificó el método tigger de Invocation Counter (PS: perdón, mi inglés es pool)

Answer 2

Voy a intentar responder a mi propia pregunta con la ayuda de este gist.github.com/1165804#file_notes.md publicado por .

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)

Primera columna

La primera columna ''260'' es la marca de tiempo.

Segunda columna

La segunda columna es el compilation_id y method_attributes. Cuando se activa una compilación de HotSpot, cada unidad de compilación obtiene un ID de compilación. El número en la segunda columna es el id de compilación. La compilación JIT y la compilación OSR tienen dos secuencias diferentes para el ID de compilación. Así que 1% y 1 son diferentes unidades de compilación. El% en las dos primeras filas, se refiere al hecho de que se trata de una compilación OSR. Se desencadenó una compilación de OSR porque el código estaba circulando en un bucle grande, y la VM determinó que este código está activo. Por lo tanto, se activó una compilación de OSR, lo que permitiría a la VM realizar un Reemplazo en la pila y pasar al código optimizado, una vez que esté listo.

Tercera columna

La tercera columna performance.api.PerformantIteration::iterateWithConstantSize es el nombre del método.

Cuarta columna

La cuarta columna es nuevamente diferente cuando ocurre la compilación OSR y cuando no lo hace. Veamos primero las partes comunes. El final de la cuarta columna (59 bytes), se refiere al tamaño de la unidad de compilación en el bytecode (no al tamaño del código compilado). La parte @ 19 en la compilación OSR se refiere a osr_bci. Voy a citar del enlace mencionado arriba -

Un "lugar" en un método Java se define por su índice de bytecode (BCI), y el lugar que activó una compilación OSR se llama "osr_bci". Un nmethod compilado por OSR solo se puede ingresar desde su osr_bci; puede haber varias versiones compiladas por OSR del mismo método al mismo tiempo, siempre que sus osr_bci difieran.

Finalmente, ¿por qué el método fue compilado dos veces?

La primera es una compilación OSR, que presumiblemente sucedió mientras se ejecutaba el bucle debido al código de calentamiento (en el ejemplo), y la segunda compilación es una compilación JIT, ¿probablemente para optimizar aún más el código compilado?