Perché due chiamate consecutive allo stesso metodo generano tempi diversi per l'esecuzione?

Question

Ecco un codice di esempio:

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

}

Questo dà il seguente output:     100     Tempo impiegato da 'fOne' ... 390273     100     Tempo impiegato da 'due' ... 118451     100     Tempo impiegato da 'fOne' ... 53359     100     Tempo impiegato da 'due' ... 115936     Premere un tasto qualsiasi per continuare . . .

Perché ci vuole più tempo (significativamente più) per eseguire lo stesso metodo per la prima volta rispetto alle chiamate consecutive?

Ho provato a dare -XX: CompileThreshold = 1000000 alla riga di comando, ma non c'erano differenze.

Answer 1

Esistono diversi motivi. Il compilatore JIT (Just In Time) potrebbe non essere stato eseguito. La JVM può eseguire ottimizzazioni che differiscono tra le invocazioni. Stai misurando il tempo trascorso, quindi forse qualcosa di diverso da Java è in esecuzione sul tuo computer. Le cache del processore e della RAM sono probabilmente "a caldo". su successive invocazioni.

Devi davvero effettuare più invocazioni (a migliaia) per ottenere un tempo di esecuzione accurato per metodo.

Answer 2

I problemi menzionati da Andreas e l'imprevedibilità di JIT sono veri, ma ancora un altro problema è il caricatore di classi :

La prima chiamata a fOne differisce radicalmente da queste ultime, perché è questo che rende la prima chiamata a System.out.println , il che significa che è quando il caricatore di classi eseguirà dalla cache del disco o del file system (di solito è memorizzato nella cache) tutte le classi necessarie per stampare il testo. Dai il parametro -verbose: class alla JVM per vedere quante classi vengono effettivamente caricate durante questo piccolo programma.

Ho notato un comportamento simile durante l'esecuzione di unit test: il primo test per chiamare un grande framework richiede molto più tempo (nel caso di Guice circa 250ms su un C2Q6600), anche se il codice di test sarebbe lo stesso, perché il primo l'invocazione avviene quando centinaia di classi vengono caricate dal programma di caricamento classi.

Poiché il programma di esempio è così breve, l'overhead probabilmente deriva dalle primissime ottimizzazioni JIT e dall'attività di caricamento della classe. Il garbage collector probabilmente non si avvia nemmeno prima che il programma sia terminato.

---

Aggiornamento:

Ora ho trovato un modo affidabile per scoprire cosa sta veramente prendendo tempo. Nessuno l'aveva ancora scoperto, sebbene sia strettamente legato al caricamento della classe: era collegamento dinamico di metodi nativi !

Ho modificato il codice come segue, in modo che i log mostrassero l'inizio e la fine dei test (osservando quando sono caricate quelle classi di marker vuote).

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

Il comando per eseguire il programma, con i parametri JVM che mostrano ciò che sta realmente accadendo:

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

E l'output:

* 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 *

E la ragione di quella differenza di orario è questa: [metodo nativo a collegamento dinamico java.io.FileOutputStream.writeBytes ... JNI]

Possiamo anche vedere che il compilatore JIT non sta influenzando questo benchmark. Esistono solo tre metodi che sono stati compilati (come java.lang.String :: indexOf nello snippet sopra) e si verificano tutti prima che venga chiamato il metodo fOne .

Answer 3

1. Il codice testato è abbastanza banale. l'azione più costosa è

    System.out.println(k);
   

   quindi quello che stai misurando è la velocità con cui viene scritto l'output di debug. Questo varia ampiamente e può anche dipendere dalla posizione della finestra di debug sullo schermo, se deve scorrere le sue dimensioni, ecc.

2. JIT / Hotspot ottimizza in modo incrementale i codepati di uso frequente.

3. Il processore ottimizza per i codepati previsti. I percorsi utilizzati più spesso vengono eseguiti più velocemente.

4. La dimensione del tuo campione è troppo piccola. Tali microbenchmark di solito fanno una fase di riscaldamento, puoi vedere quanto questo dovrebbe essere fatto ampiamente come Java è davvero veloce nel non fare nulla .

Answer 4

Oltre a JITting, altri fattori potrebbero essere:

• Blocco del flusso di output del processo quando si chiama System.out.println
• Il processo viene pianificato da un altro processo
• Il garbage collector sta facendo un po 'di lavoro su un thread in background

Se vuoi ottenere buoni benchmark, dovresti

• Esegui il codice che stai confrontando un gran numero di volte, almeno diverse migliaia, e calcola il tempo medio.
• Ignora i tempi delle prime numerose chiamate (a causa di JITting, ecc.)
• Disabilita il GC se puoi; questa potrebbe non essere un'opzione se il tuo codice genera molti oggetti.
• Estrai la registrazione (chiamate println) dal codice di riferimento.

Esistono librerie di benchmarking su diverse piattaforme che ti aiuteranno a fare queste cose; possono anche calcolare deviazioni standard e altre statistiche.

Answer 5

Il colpevole più probabile è il JIT (motore just-in-time) hotspot. Fondamentalmente il primo time code viene eseguito il codice macchina è "ricordato" dalla JVM e poi riutilizzato per future esecuzioni.

Answer 6

Penso che sia perché la seconda volta il codice generato è già stato ottimizzato, dopo la prima esecuzione.

Answer 7

Come è stato suggerito, JIT potrebbe essere il colpevole, ma anche il tempo di attesa I / O e il tempo di attesa delle risorse se altri processi sulla macchina stessero utilizzando le risorse in quel momento.

La morale di questa storia è che il micrbenchmarking è un problema difficile, specialmente per Java. Non so perché lo stai facendo, ma se stai cercando di scegliere tra due approcci per un problema, non misurarli in questo modo. Utilizzare il modello di progettazione della strategia ed eseguire l'intero programma con i due diversi approcci e misurare l'intero sistema. Ciò rende i piccoli aumenti dei tempi di elaborazione anche a lungo termine e ti dà una visione molto più realistica di quanto le prestazioni dell'intera app siano strozzate a quel punto (suggerimento: probabilmente è inferiore a quanto pensi.)

Answer 8

Beh, la risposta più probabile è l'inizializzazione. JIT non è sicuramente la risposta giusta in quanto richiede molti più cicli prima di iniziare a ottimizzare. Ma alla prima volta ci possono essere:

• ricerca di classi (viene memorizzata nella cache, quindi non è necessaria una seconda ricerca)
• caricamento classi (una volta caricato rimane in memoria)
• ottenere ulteriore codice dalla libreria nativa (il codice nativo viene memorizzato nella cache)
• infine carica il codice da eseguire nella cache L1 della CPU. Questo è il caso più propizio per l'accelerazione nel tuo senso e allo stesso tempo un motivo per cui il benchmark (essendo un microbenchmark) non dice molto. Se il tuo codice è abbastanza piccolo, la seconda invocazione di un loop può essere eseguita completamente dall'interno della CPU, il che è veloce. Nel mondo reale ciò non accade perché i programmi sono più grandi e il riutilizzo della cache L1 è lungi dall'essere così grande.