Ho un problema di prestazioni Java che non capisco

Question

Ho scritto un po 'di codice per creare una matrice multidimensionale piuttosto che una matrice di array in modo da poter risparmiare un po' di memoria. Quindi ho eseguito alcuni test per confrontare la sua velocità con quella del normale array di array Java (int [] []) in quanto non voglio che il mio programma funzioni più lentamente anche se salva della memoria. Ciò che ho visto nei test di temporizzazione mi ha confuso. Ecco i risultati tipici per una corsa di prova. I tempi sono per lo stesso bit di codice. Nota come gli ultimi due sono molto più grandi dei primi quattro.

tempo: 58343722 ns
tempo: 59451156 ns
tempo: 51374777 ns

tempo: 61777424 ns
tempo: 813156695 ns
tempo: 782140511 ns

Ora la La prima cosa che ho pensato è stato il raccoglitore di rifiuti che ha dato il calcio. Ho alzato il limite di memoria a 5 GB (-Xmx5g) in modo che il netturbino con aria di sfida Non iniziare. Niente è cambiato. Ho spostato le cose, ma il modello rimane.

Quindi qual è lo schema? Nelle prime tre volte, il bit di codice è in una funzione e io lo chiamo tre volte. Nel secondo tre volte il bit di codice viene ripetuto in una singola funzione tre volte. In modo che il modello è che ogni volta che il bit di codice viene eseguito più volte nella stessa funzione, il tempo necessario per eseguire il bit di codice verrà avviato a partire dal secondo bit di codice e resterà lì dopo.

Ho trovato un'alterazione che produrrà risultati come questo:

tempo: 58729424 ns
tempo: 59965426 ns
tempo: 51441618 ns

tempo: 57359741 ns
tempo: 65362705 ns
tempo: 857942387 ns

Quello che ho fatto è stato aggiungere un ritardo di un millisecondo tra i bit di codice dei secondi tre. In questo modo si accelera solo il secondo dei bit di codice nel blocco e nessuna quantità di ritardo accelera i bit di codice lì dopo.

Francamente, sono confuso. Non posso spiegare questo comportamento. Qualcuno può far luce su quello che sta succedendo?

Ecco il codice:

package multidimensionalarraytests; 

import java.lang.reflect.Array; 
import java.util.logging.Level; 
import java.util.logging.Logger; 

public class MultidimensionalArrayTests { 
    static ArrayInt2Dv1 array=new ArrayInt2Dv1(10000,10000); 

    public static void main(String[] args) { 
     System.out.println("ignore the warmup"); 
     test(); 
     test(); 
     combined(); 
     combined(); 

     System.out.println("running tests"); 
     test(); 
     test(); 
     test(); 
     System.out.println(); 
     combined(); 
    } 

    static long test(){ 
     int value=1; 
     long start,stop,time; 

     System.out.print("time: "); 
     start=System.nanoTime(); 
     for(int x=0;x<array.length1;x++){ 
      for(int y=0;y<array.length2;y++){ 
       array.set(x, y, value); 
       value=array.get(x, y); 
      } 
     } 
     stop=System.nanoTime(); 
     time=(stop-start); 
     System.out.println(time+" ns"); 
     return time; 
    } 

    static void combined(){ 
     int value=1; 
     long start,stop,time; 

     System.out.print("time: "); 
     start=System.nanoTime(); 
     for(int x=0;x<array.length1;x++){ 
      for(int y=0;y<array.length2;y++){ 
       array.set(x, y, value); 
       value=array.get(x, y); 
      } 
     } 
     stop=System.nanoTime(); 
     time=(stop-start); 
     System.out.println(time+" ns"); 

     //try {Thread.sleep(1);} catch (InterruptedException ex) {} 

     System.out.print("time: "); 
     start=System.nanoTime(); 
     for(int x=0;x<array.length1;x++){ 
      for(int y=0;y<array.length2;y++){ 
       array.set(x, y, value); 
       value=array.get(x, y); 
      } 
     } 
     stop=System.nanoTime(); 
     time=(stop-start); 
     System.out.println(time+" ns"); 

     //try {Thread.sleep(60000);} catch (InterruptedException ex) {} 

     System.out.print("time: "); 
     start=System.nanoTime(); 
     for(int x=0;x<array.length1;x++){ 
      for(int y=0;y<array.length2;y++){ 
       array.set(x, y, value); 
       value=array.get(x, y); 
      } 
     } 
     stop=System.nanoTime(); 
     time=(stop-start); 
     System.out.println(time+" ns");  
    } 
} 

e:

package multidimensionalarraytests; 

public class ArrayInt2Dv1 { 
    int [] array; 

    public final int length1; 
    public final int length2; 

    public ArrayInt2Dv1(int length1, int length2){ 
     this.length1=length1; 
     this.length2=length2; 
     array=new int[length1*length2]; 
    } 

    public int get(int x,int y){ 
     return array[x*length2+y]; 
    } 

    public void set(int x,int y,int value){ 
     array[x*length2+y]=value; 
    } 
} 

--- --- Modifica

L'uscita su Windows 7 con le opzioni -Xms5g -Xmx5g -XX: + PrintCompilation -verbose: gc -XX: CICompilerCount = 1 -Xbatch

time:  299 1 b  multidimensionalarraytests.ArrayInt2Dv1::set (15 bytes) 
    302 2 b  multidimensionalarraytests.ArrayInt2Dv1::get (14 bytes) 
    303 1 % b  multidimensionalarraytests.MultidimensionalArrayTests::test @ 31 (114 bytes) 
    358 1 %   multidimensionalarraytests.MultidimensionalArrayTests::test @ -2 (114 bytes) made not entrant 
60671451 ns 
    359 3 b  multidimensionalarraytests.MultidimensionalArrayTests::test (114 bytes) 
time:  365 2 % b  multidimensionalarraytests.MultidimensionalArrayTests::test @ 31 (114 bytes) 
58104484 ns 
time:  425 3 % b  multidimensionalarraytests.MultidimensionalArrayTests::combined @ 31 (330 bytes) 
69008251 ns 
time: 806898159 ns 
time: 845447596 ns 
    2146 4 b  multidimensionalarraytests.MultidimensionalArrayTests::combined (330 bytes) 
time: 52493169 ns 
time: 804304528 ns 
time: 845500191 ns 
running tests 
time: 51290771 ns 
time: 51922285 ns 
time: 51264108 ns 

time: 52258679 ns 
time: 842229025 ns 
time: 871403625 ns 

Su Linux (Ubuntu su VirtualBox sulla stessa macchina) con le stesse opzioni:

283 1 b java.lang.String::hashCode (60 bytes) 
    285 2 b sun.nio.cs.UTF_8$Encoder::encodeArrayLoop (490 bytes) 
    287 3 b java.lang.String::charAt (33 bytes) 
    287 4 b java.lang.String::indexOf (151 bytes) 
    297 5 b java.io.UnixFileSystem::normalize (75 bytes) 
    2850 6 b java.lang.String::lastIndexOf (156 bytes) 
ignore the warmup 
time: 5885 7 b multidimensionalarraytests.ArrayInt2Dv1::set (15 bytes) 
    5948 8 b multidimensionalarraytests.ArrayInt2Dv1::get (14 bytes) 
    5949 1% b multidimensionalarraytests.MultidimensionalArrayTests::test @ 31 (114 bytes) 
11529998483 ns 
    17565 9 b multidimensionalarraytests.MultidimensionalArrayTests::test (114 bytes) 
time: 1619622928 ns 
time: 19718 2% b multidimensionalarraytests.MultidimensionalArrayTests::combined @ 31 (330 bytes) 
475786382 ns 
time: 288586857 ns 
time: 315560700 ns 
    20789 10 b multidimensionalarraytests.MultidimensionalArrayTests::combined (330 bytes) 
time: 460577230 ns 
time: 311525066 ns 
time: 312343429 ns 
running tests 
time: 310261854 ns 
time: 298826592 ns 
time: 304689920 ns 

time: 315416579 ns 
time: 299473245 ns 
time: 290211350 ns 

Answer 1

Prova -XX:+PrintCompilation Questo dovrebbe dimostrare che l'intero metodo è ottimizzato dopo il primo ciclo itera 10000 volte. Il problema è che il secondo/terzo ciclo è ottimizzato senza informazioni statistiche/contatore. A volte questo non ha importanza, a volte i loop successivi sono molto più lenti e se si cambia l'ordine dei loop, i loop successivi migliorano e il primo ciclo rallenta.

Il modo semplice per risolvere questo problema consiste nel posizionare ciascun ciclo nel proprio metodo e ciascun ciclo verrà ottimizzato correttamente.