Perché questo loop interno 4X più veloce è la prima iterazione attraverso il loop esterno?

Question

Stavo cercando di riprodurre alcuni degli effetti della cache del processore descritti in here. Capisco che Java è un ambiente gestito, e questi esempi non tradurrò esattamente, ma mi sono imbattuto in uno strano caso, che ho cercato di distillare a un semplice esempio che illustra l'effetto:

public static void main(String[] args) { 
    final int runs = 10; 
    final int steps = 1024 * 1024 * 1024; 

    for (int run = 0; run < runs; run++) { 
     final int[] a = new int[1]; 
     long start = System.nanoTime(); 
     for (int i = 0; i < steps; i++) { 
      a[0]++; 
     } 
     long stop = System.nanoTime(); 
     long time = TimeUnit.MILLISECONDS.convert(stop - start, TimeUnit.NANOSECONDS); 
     System.out.printf("Time for loop# %2d: %5d ms\n", run, time); 
    } 
} 

uscita:

Time for loop# 0: 24 ms 
Time for loop# 1: 106 ms 
Time for loop# 2: 104 ms 
Time for loop# 3: 103 ms 
Time for loop# 4: 102 ms 
Time for loop# 5: 103 ms 
Time for loop# 6: 104 ms 
Time for loop# 7: 102 ms 
Time for loop# 8: 105 ms 
Time for loop# 9: 102 ms 

La prima iterazione dell'anello interno è circa 4 volte più veloce delle iterazioni successive. Questo è l'opposto di quello che normalmente mi aspetterei, dato che solitamente le performance salgono quando il JIT calcia.

Ovviamente, si farebbero diversi cicli di riscaldamento in qualsiasi serio micro-benchmark, ma sono curioso di a ciò che potrebbe causare questo comportamento, soprattutto perché se sappiamo che il ciclo può essere eseguito in 24 ms, non è molto soddisfacente che il tempo di stato stazionario sia superiore a 100 ms.

Per riferimento JDK sto usando (su linux):

openjdk version "1.8.0_40" 
OpenJDK Runtime Environment (build 1.8.0_40-b20) 
OpenJDK 64-Bit Server VM (build 25.40-b23, mixed mode) 

UPDATE:

Ecco alcune informazioni di aggiornamento, sulla base di alcuni dei commenti, e alcuni esperimenti:

1) lo spostamento del System.out I/O fuori dal loop (memorizzando i tempi in un array di dimensioni 'runs') non fa alcuna differenza significativa in termini di tempo.

2) l'output visualizzato sopra è quando corro da Eclipse. Quando compilo e corro dalla riga di comando (con lo stesso JDK/JVM) ottengo risultati più modesti, ma comunque significativi (2x invece di 4x più veloce). Questo sembra interessante, dal momento che usaully in esecuzione in eclissi rallenterà le cose, se non altro.

3) spostamento a su, fuori dal ciclo, in modo che venga riutilizzato ogni iterazione non ha alcun effetto.

4) se int[] a viene modificato in long[] a, la prima iterazione viene eseguita ancora più velocemente (circa il 20%), mentre le altre iterazioni sono sempre la stessa (più lenta) velocità.

UPDATE 2:

Penso che la risposta da apangin lo spiega. Ho provato questo con 1.9 JVM di Sun e sta andando da:

openjdk version "1.8.0_40" 
OpenJDK Runtime Environment (build 1.8.0_40-b20) 
OpenJDK 64-Bit Server VM (build 25.40-b23, mixed mode) 

Time for loop# 0: 48 ms 
Time for loop# 1: 116 ms 
Time for loop# 2: 112 ms 
Time for loop# 3: 113 ms 
Time for loop# 4: 112 ms 
Time for loop# 5: 112 ms 
Time for loop# 6: 111 ms 
Time for loop# 7: 111 ms 
Time for loop# 8: 113 ms 
Time for loop# 9: 113 ms 

a:

java version "1.9.0-ea" 
Java(TM) SE Runtime Environment (build 1.9.0-ea-b73) 
Java HotSpot(TM) 64-Bit Server VM (build 1.9.0-ea-b73, mixed mode) 

Time for loop# 0: 48 ms 
Time for loop# 1: 26 ms 
Time for loop# 2: 22 ms 
Time for loop# 3: 22 ms 
Time for loop# 4: 22 ms 
Time for loop# 5: 22 ms 
Time for loop# 6: 22 ms 
Time for loop# 7: 22 ms 
Time for loop# 8: 22 ms 
Time for loop# 9: 23 ms 

Questo è piuttosto il miglioramento!

Answer 1

Questa è una ricompilazione non ottimale di un metodo.

Il compilatore JIT si basa su statistiche di runtime raccolte durante l'interpretazione. Quando il metodo main viene compilato per la prima volta, il ciclo esterno non ha ancora completato la sua prima iterazione => le statistiche di runtime indicano che il codice dopo il ciclo interno non viene mai eseguito, quindi JIT non si preoccupa mai di compilarlo. Piuttosto genera una trappola non comune.

Quando l'anello interno termina per la prima volta, la trappola non comune viene colpita causando la deoptimizzazione del metodo.

Sulla seconda iterazione del ciclo esterno il metodo main viene ricompilato con le nuove conoscenze. Ora JIT ha più statistiche e più contesto da compilare. Per qualche ragione ora non memorizza nel registro il valore a[0] (probabilmente perché il JIT è ingannato dal contesto più ampio). Quindi genera l'istruzione addl per aggiornare l'array in memoria, che è effettivamente una combinazione di carico di memoria e memorizzazione.

Al contrario, durante la prima compilazione JIT memorizza nella cache il valore di a[0] nel registro, c'è solo l'istruzione mov per memorizzare un valore in memoria (senza carico).

fast loop (prima iterazione):

0x00000000029fc562: mov %ecx,0x10(%r14) <<< array store 
0x00000000029fc566: mov %r11d,%edi 
0x00000000029fc569: mov %r9d,%ecx 
0x00000000029fc56c: add %edi,%ecx 
0x00000000029fc56e: mov %ecx,%r11d 
0x00000000029fc571: add $0x10,%r11d  <<< increment in register 
0x00000000029fc575: mov %r11d,0x10(%r14) <<< array store 
0x00000000029fc579: add $0x11,%ecx 
0x00000000029fc57c: mov %edi,%r11d 
0x00000000029fc57f: add $0x10,%r11d 
0x00000000029fc583: cmp $0x3ffffff2,%r11d 
0x00000000029fc58a: jl  0x00000000029fc562 

ciclo lento (dopo ricompilazione):

0x00000000029fa1b0: addl $0x10,0x10(%r14) <<< increment in memory 
0x00000000029fa1b5: add $0x10,%r13d 
0x00000000029fa1b9: cmp $0x3ffffff1,%r13d 
0x00000000029fa1c0: jl  0x00000000029fa1b0 

Tuttavia questo problema sembra essere fissato JDK 9. Ho controllato questo test contro una recente versione di Accesso rapido JDK 9 e verificato che funzioni come previsto:

Time for loop# 0: 104 ms 
Time for loop# 1: 101 ms 
Time for loop# 2: 91 ms 
Time for loop# 3: 63 ms 
Time for loop# 4: 60 ms 
Time for loop# 5: 60 ms 
Time for loop# 6: 59 ms 
Time for loop# 7: 55 ms 
Time for loop# 8: 57 ms 
Time for loop# 9: 59 ms