Warum liefern zwei aufeinanderfolgende Aufrufe derselben Methode unterschiedliche Zeiten für die Ausführung?

Question

Hier ist ein Beispielcode:

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

}

Dies gibt die folgende Ausgabe: 100 Zeit von 'Fone' ... 390273 100 Zeit von 'ftwo' ... 118451 100 Zeit von 'Fone' ... 53359 100 Zeit von 'ftwo' ... 115936 Drücken Sie eine beliebige Taste, um fortzufahren . . .

Warum dauert es mehr Zeit (wesentlich mehr), um die gleiche Methode zum ersten Mal auszuführen wie die aufeinanderfolgenden Anrufe?

Ich habe versucht zu geben -XX:CompileThreshold=1000000 zur Befehlszeile, aber es gab keinen Unterschied.

Answer 1

Es gibt verschiedene Gründe. Der JIT -Compiler (gerade rechtzeitig) ist möglicherweise nicht ausgeführt. Das JVM kann Optimierungen durchführen, die sich zwischen den Aufrufe unterscheiden. Sie messen verstrichene Zeit, also läuft vielleicht etwas anderes als Java auf Ihrer Maschine. Die Prozessor- und RAM -Caches sind bei nachfolgenden Aufrufe wahrscheinlich "warm".

Sie müssen wirklich mehrere Aufrufe (zu Tausenden) vornehmen, um eine genaue Ausführungszeit pro Methode zu erhalten.

Answer 2

Die Probleme erwähnt von Andreas Und die Unvorhersehbarkeit von JIT ist wahr, aber noch ein weiteres Problem ist das Klassenlader:

Der erste Anruf bei fOne unterscheidet sich radikal von den letzteren, denn das macht den ersten Anruf dazu System.out.println, Dies bedeutet, dass der Klassenlader aus dem Festplatten- oder Dateisystem -Cache (normalerweise zwischengespeichert wird) alle Klassen, die zum Drucken des Textes benötigt werden. Geben Sie den Parameter an -verbose:class an die JVM, um zu sehen, wie viele Klassen während dieses kleinen Programms tatsächlich geladen sind.

Ich habe ein ähnliches Verhalten beim Ausführen von Unit -Tests bemerkt - der erste Test, der ein großes Framework aufruft Hunderte von Klassen werden vom Klassenlader geladen.

Da Ihr Beispielprogramm so kurz ist, stammt der Overhead wahrscheinlich aus den sehr frühen JIT -Optimierungen und der Klassenladungsaktivität. Der Müllsammler wird wahrscheinlich nicht einmal vor dem Ende des Programms beginnen.

---

Aktualisieren:

Jetzt fand ich eine verlässliche Möglichkeit, herauszufinden, was ist Ja wirklich Zeit nehmen. Niemand hatte es noch herausgefunden, obwohl es eng mit der Klassenbelastung zusammenhängt - es war es Dynamische Verknüpfung nativer Methoden!

Ich habe den Code wie folgt geändert, damit die Protokolle angezeigt werden, wenn die Tests beginnen und enden (indem diese leeren Markierungsklassen geladen werden).

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

Der Befehl zum Ausführen des Programms mit dem Recht JVM -Parameter Das zeigt, was wirklich passiert:

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

Und die Ausgabe:

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

Und der Grund für diesen Zeitunterschied ist Folgendes: [Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]

Wir können auch sehen, dass der JIT -Compiler diesen Benchmark nicht beeinflusst. Es gibt nur drei Methoden, die zusammengestellt werden (z. java.lang.String::indexOf im obigen Snippet) und sie alle passieren vor dem fOne Methode heißt.

Answer 3

1. Der getestete Code ist ziemlich trivial. Die teuersten Maßnahmen sind

    System.out.println(k);
   

   Sie messen also, wie schnell der Debug -Ausgang geschrieben ist. Dies variiert sehr und kann sogar von der Position des Debug -Fensters auf dem Bildschirm abhängen, wenn es seine Größe usw. scrollen muss usw.

2. JIT/Hotspot optimiert inkrementell häufig verwendete Codepaths.

3. Der Prozessor optimiert für erwartete Codepaths. Wege werden häufiger schneller ausgeführt.

4. Ihre Stichprobengröße ist viel zu klein. Solche Mikrobenchmarks führen normalerweise eine Aufwärmphase aus Java ist sehr schnell darin, nichts zu tun.

Answer 4

Zusätzlich zu Jitting könnten andere Faktoren sein:

• Der Ausgangsstream des Prozesses blockiert, wenn Sie system.out.println aufrufen
• Ihr Prozess wird durch einen anderen Prozess geplant
• Der Müllsammler, der etwas Arbeit auf einem Hintergrundfaden macht

Wenn Sie gute Benchmarks bekommen möchten, sollten Sie sollten

• Führen Sie den Code aus, den Sie viel Male benchmarkieren, mindestens mehrere Tausend und berechnen Sie die durchschnittliche Zeit.
• Ignorieren Sie die Zeiten der ersten Anrufe (aufgrund von Jitting usw.)
• Deaktivieren Sie das GC, wenn Sie können; Dies ist möglicherweise keine Option, wenn Ihr Code viele Objekte generiert.
• Nehmen Sie die Protokollierung (Println -Anrufe) aus dem zu einem Benchmarked bewerteten Code.

Auf mehreren Plattformen gibt es Benchmarking -Bibliotheken, die Ihnen helfen, dieses Zeug zu tun. Sie können auch Standardabweichungen und andere Statistiken berechnen.

Answer 5

Der wahrscheinlichste Schuldige ist der Jit (Just-in-Time) Hotspot Engine. Grundsätzlich wird das erste Mal, dass Code ausgeführt wird, der Maschinencode wird von der JVM "in Erinnerung" und wird dann zukünftige Ausführungen wiederverwendet.

Answer 6

Ich denke, das liegt daran, dass nach dem ersten Lauf das zweite Mal der generierte Code bereits optimiert wurde.

Answer 7

As has been suggested, JIT could be the culprit, but so could I/O wait time as well as resource wait time if other processes on the machine were using resources at that moment.

The moral of this story is that micrbenchmarking is a hard problem, especially for Java. I don't know why you're doing this, but if you're trying to choose between two approaches for a problem, don't measure them this way. Use the strategy design pattern and run your entire program with the two different approaches and measure the whole system. That makes little bumps in processing time even out over the long run, and gives you a much more realistic view of how much the performance of your entire app is bottlenecked at that point (hint: it's probably less than you think.)

Answer 8

Well the most probably answer is initialization. JIT is for sure not the right answer as it takes a lot more cycles before it starts to optimize. But at the very first time there can be:

• looking up classes (is cached so no second lookup needed)
• loading classes (once loaded stays in memory)
• getting additional code from the native library (native code is cached)
• finally it loads the code to be executed in the L1 cache of the CPU. That is the most propable case for speedup in your sense and at the same time a reason why the benchmark (being a microbenchmark) does not say much. If your code is small enough the second invocation of a loop can be run completely from inside the CPU which is fast. In the real world this does not happen because programs are bigger and the reusage of the L1 cache is far from being that big.