¿Por qué dos llamadas consecutivas al mismo método producen tiempos diferentes para la ejecución?

Question

Aquí hay un código de ejemplo:

public class TestIO{
public static void main(String[] str){
    TestIO t = new TestIO();
    t.fOne();
    t.fTwo();
    t.fOne();
    t.fTwo();
}


public void fOne(){
    long t1, t2;
    t1 = System.nanoTime();
    int i = 10;
    int j = 10;
    int k = j*i;
    System.out.println(k);
    t2 = System.nanoTime();
    System.out.println("Time taken by 'fOne' ... " + (t2-t1));
}

public void fTwo(){
    long t1, t2;
    t1 = System.nanoTime();
    int i = 10;
    int j = 10;
    int k = j*i;
    System.out.println(k);
    t2 = System.nanoTime();
    System.out.println("Time taken by 'fTwo' ... " + (t2-t1));
}

}

Esto da el siguiente resultado:     100     Tiempo tomado por 'fOne' ... 390273     100     Tiempo tomado por 'fTwo' ... 118451     100     Tiempo tomado por 'fOne' ... 53359     100     Tiempo tomado por 'fTwo' ... 115936     Pulse cualquier tecla para continuar . . .

¿Por qué lleva más tiempo (significativamente más) ejecutar el mismo método por primera vez que las llamadas consecutivas?

Intenté dar -XX: CompileThreshold = 1000000 a la línea de comando, pero no hubo diferencia.

Answer 1

Hay varias razones. Es posible que el compilador JIT (Just In Time) no se haya ejecutado. La JVM puede hacer optimizaciones que difieren entre invocaciones. Está midiendo el tiempo transcurrido, así que tal vez se esté ejecutando en su máquina algo distinto de Java. Las memorias caché del procesador y de la memoria RAM son probablemente "cálidas" en las invocaciones posteriores.

Realmente necesitas hacer múltiples invocaciones (en miles) para obtener un tiempo de ejecución preciso por método.

Answer 2

Los problemas mencionados por Andreas y la imprevisibilidad de JIT son ciertas, pero aún un problema más es el cargador de clases :

La primera llamada a fOne difiere radicalmente de las últimas, porque eso es lo que hace la primera llamada a System.out.println , lo que significa que es cuando El cargador de clases tomará del disco o del caché del sistema de archivos (generalmente se almacena en caché) todas las clases necesarias para imprimir el texto. Proporcione el parámetro -verbose: class a la JVM para ver cuántas clases se cargan realmente durante este pequeño programa.

He notado un comportamiento similar al ejecutar pruebas unitarias: la primera prueba para llamar a un marco grande toma mucho más tiempo (en el caso de Guice, aproximadamente 250 ms en un C2Q6600), aunque el código de prueba sería el mismo, porque la primera la invocación es cuando el cargador de clases carga cientos de clases.

Dado que su programa de ejemplo es tan corto, la sobrecarga probablemente proviene de las optimizaciones JIT muy tempranas y la actividad de carga de clases. Es probable que el recolector de basura ni siquiera comience antes de que finalice el programa.

---

Actualización :

Ahora encontré una manera confiable de averiguar qué realmente se toma el tiempo. Nadie lo había descubierto aún, aunque está estrechamente relacionado con la carga de clases, ¡era enlace dinámico de métodos nativos !

Modifiqué el código de la siguiente manera, para que los registros se muestren cuando comiencen y terminen las pruebas (mirando cuando se cargan esas clases de marcadores vacías).

    TestIO t = new TestIO();
    new TestMarker1();
    t.fOne();
    t.fTwo();
    t.fOne();
    t.fTwo();
    new TestMarker2();

El comando para ejecutar el programa, con el derecho Parámetros JVM que muestran lo que realmente está sucediendo:

java -verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation TestIO

Y la salida:

* snip 493 lines *
[Loaded java.security.Principal from shared objects file]
[Loaded java.security.cert.Certificate from shared objects file]
[Dynamic-linking native method java.lang.ClassLoader.defineClass1 ... JNI]
[Loaded TestIO from file:/D:/DEVEL/Test/classes/]
  3       java.lang.String::indexOf (166 bytes)
[Loaded TestMarker1 from file:/D:/DEVEL/Test/classes/]
[Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
100
Time taken by 'fOne' ... 155354
100
Time taken by 'fTwo' ... 23684
100
Time taken by 'fOne' ... 22672
100
Time taken by 'fTwo' ... 23954
[Loaded TestMarker2 from file:/D:/DEVEL/Test/classes/]
[Loaded java.util.AbstractList$Itr from shared objects file]
[Loaded java.util.IdentityHashMap$KeySet from shared objects file]
* snip 7 lines *

Y la razón de esa diferencia horaria es esta: [método nativo de enlace dinámico java.io.FileOutputStream.writeBytes ... JNI]

También podemos ver, que el compilador JIT no está afectando a este punto de referencia. Solo se compilan tres métodos (como java.lang.String :: indexOf en el fragmento de código anterior) y todos ocurren antes de que se llame al método fOne .

Answer 3

1. El código probado es bastante trivial. La acción más costosa tomada es

    System.out.println(k);
   

   así que lo que estás midiendo es qué tan rápido se escribe la salida de depuración. Esto varía ampliamente, e incluso puede depender de la posición de la ventana de depuración en la pantalla, si necesita desplazarse por su tamaño, etc.

2. JIT / Hotspot optimiza de forma incremental las rutas de código de uso frecuente.

3. El procesador optimiza para las rutas de código esperadas. Las rutas utilizadas con más frecuencia se ejecutan más rápido.

4. El tamaño de la muestra es demasiado pequeño. Tales microbenchmarks usualmente hacen una fase de calentamiento, puedes ver cuán ampliamente se debe hacer, como Java es realmente rápido en no hacer nada .

Answer 4

Además de JITting, otros factores podrían ser:

• El bloqueo de la secuencia de salida del proceso cuando llama a System.out.println
• Tu proceso está programado para otro proceso
• El recolector de basura que está trabajando en un hilo de fondo

Si desea obtener buenos puntos de referencia, debería

• Ejecute el código en el que está haciendo una evaluación comparativa una gran cantidad de veces, al menos varios miles, y calcule el tiempo promedio.
• Ignora los tiempos de las primeras llamadas (debido a JITting, etc.)
• Deshabilita el GC si puedes; esto puede no ser una opción si su código genera muchos objetos.
• Saque el registro (llamadas println) del código que se está evaluando.

Hay bibliotecas de puntos de referencia en varias plataformas que te ayudarán a hacer esto; también pueden calcular desviaciones estándar y otras estadísticas.

Answer 5

El culpable más probable es el JIT (justo a tiempo) del motor del hotspot. Básicamente, la primera vez que se ejecuta el código, el código de máquina se " recuerda " por la JVM y luego reutilizada en futuras ejecuciones.

Answer 6

Creo que es porque la segunda vez que el código generado ya estaba optimizado, después de la primera ejecución.

Answer 7

Como se ha sugerido, JIT podría ser el culpable, pero también el tiempo de espera de E / S y el tiempo de espera de recursos si otros procesos en la máquina estuvieran usando recursos en ese momento.

La moraleja de esta historia es que las marcas de microfiguración son un problema difícil, especialmente para Java. No sé por qué está haciendo esto, pero si está tratando de elegir entre dos enfoques para un problema, no los mida de esta manera. Use el patrón de diseño de estrategia y ejecute todo su programa con los dos enfoques diferentes y mida todo el sistema. Eso hace que el tiempo de procesamiento se convierta en un pequeño obstáculo a largo plazo, y le brinda una visión mucho más realista de cuánto se bloquea el rendimiento de toda la aplicación en ese punto (sugerencia: probablemente sea menos de lo que cree).

Answer 8

Bueno, la respuesta más probable es la inicialización. JIT no es la respuesta correcta, ya que lleva muchos más ciclos antes de que empiece a optimizar. Pero a la primera vez puede haber:

• buscar clases (se almacena en caché, por lo que no se necesita una segunda búsqueda)
• cargar clases (una vez cargadas permanece en la memoria)
• obtener código adicional de la biblioteca nativa (el código nativo se almacena en caché)
• finalmente carga el código que se ejecutará en el caché L1 de la CPU. Ese es el caso más propicio para la aceleración en su sentido y, al mismo tiempo, una razón por la cual el punto de referencia (ser un microbado) no dice mucho. Si su código es lo suficientemente pequeño, la segunda invocación de un bucle puede ejecutarse completamente desde el interior de la CPU, lo cual es rápido. En el mundo real esto no sucede porque los programas son más grandes y la reutilización de la memoria caché L1 está lejos de ser tan grande.