java - Entendiendo la salida de-XX:+PrintCompilation
microbenchmark (2)
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)
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?
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?