Naive Laufzeitmessung

[blz]

Habe das unten stehende Programm geschrieben, um die Laufzeiten von verschiedenen Operationen zu messen.
Mir ist schon klar, dass es da keine exakten Ergebnisse geben wird. Nun bekomme ich allerdings beim Aufruf von laufzeitMessen() immer Ausgaben wie folgende:



Da die Zahlen immer Vielfache von 100 sind: Kann es sein, dass meine Systemzeit einfach nicht genauer als auf Zehntelmikrosekunden ist und ich deshalb gerundete Werte bekomme? (Alles unter 50 wird dann wohl auf 0 abgerundet?)

import java.util.*;

class Laufzeitmessung {

    int i = 0;

    /**
     * Methode zum Testen der Laufzeit einer anderen Methode, die unterhalb des Kommentars aufgerufen werden muss.
     * @return Ausführungsdauer
     */
    public void laufzeitTesten()
    {
        long minimum;
        minimum = Integer.MAX_VALUE;
        long startzeit;
        long laufzeit;

        for (int i = 0; i < 1000; i++)
        {           
            startzeit = System.nanoTime();
            
            this.inkrementieren();
            
            laufzeit = System.nanoTime() - startzeit;
            if (laufzeit < minimum)
            {
                minimum = laufzeit;
            }
            System.out.println("Dauer Objekterzeugung (in ns): " + laufzeit);
        }
        System.out.println("Minimum (in ns): " + minimum);

    }

    /**
     * Beispielmethode erzeugt ein Objekt
     */
    public void objektErzeugen()
    {
        new Schrittzaehlung();
    }

    /**
     * Beispielmethode erzeugt ein Feld
     */
    public void feldErzeugen()
    {
        int[] feld = new int[10];
    }

    /**
     * Beispielmethode inkrementiert den Wert eines Attributs
     */ 
    public void inkrementieren()
    {
        i++;
    }
}

 

[Robert Zenz]

Uff, du misst hier eine Operation die wahrscheinlich nur in 5 CPU-Instruktionen ausartet. Ich denke nicht dass du dafuer brauchbare Messwerte bekommen kannst, zumindest nicht "auf normalen Weg". Besser waere es wenn du deine Schleife auf 1 Million Durchlaeufe aenderst, und deine gesamte Schleife misst, und das Ergebnis dann durch 1 Million dividierst.

Die Operation die du da versuchst zu messen ist einfach viel, viel, viel zu wenig um irgendein brauchbares Ergebnis zu erhalten. Vermutlich ist sogar der System.nanoTime() Aufruf teurer als die Operation welche du misst.

Wenn ich so darueber nachdenke, wird wahrscheinlich sogar 1 Million zu wenig Durchlaeufe sein, vielleicht waere Integer.MAX_VALUE ein guter Anfang.

 

[KonradN]

Ja, Deine Sichtweise dürfte soweit richtig sein.

Die ganze Thematik ist aber deutlich komplexer - so gibt es bei den Aufrufen auch noch eine Latenz und so.

Nanotrusting the Nanotime

wäre ein Blog, der das auch etwas näher betrachtet. Und das Ergebnis am Ende wäre da:

In all seriousness, we should be happy our $1000 hardware can measure 30 nanosecond intervals pretty reliably. This is roughly the time needed for the Internet packets originating from my home router to leave my apartment. What else do you want, you spoiled brats?

 

[temi]

Zusätzlich kommen erschwerend noch Effekte der Runtime-Umgebung hinzu, so dass Programme, sozusagen, erst mal "warm" laufen müssen.

Es gibt aber auch Software-Bibliotheken, die hier helfen können, z. B. JMH

 

[Robert Zenz]

Zusätzlich kommen erschwerend noch Effekte der Runtime-Umgebung hinzu, so dass Programme, sozusagen, erst mal "warm" laufen müssen.

Das spielt in dem Fall aber keine Rolle (soweit ich weisz spielt das Primaer eine Rolle wenn man viele ifs hat, weil dann die Pfade optimiert werden), kann mich aber auch irren.

 

[temi]

Das spielt in dem Fall aber keine Rolle (soweit ich weisz spielt das Primaer eine Rolle wenn man viele ifs hat, weil dann die Pfade optimiert werden), kann mich aber auch irren.

Wer weiß schon genau, was eine JVM so macht?

 

[ing0-bing0]

Du darfst nicht eine einzelne Objektinstanziierung messen, sondern zum Beispiel 1000 oder so. Die Summe kannst du dann durch die Anzahl der Iterationen teilen.

Außerdem musst du sicherstellen, dass die Schleife nicht optimiert wird.

 

[temi]

Du darfst nicht eine einzelne Objektinstanziierung messen, sondern zum Beispiel 1000 oder so. Die Summe kannst du dann durch die Anzahl der Iterationen teilen.

Wiederholst du jetzt immer bereits gegebene Antworten?

 

[ing0-bing0]

import java.util.concurrent.atomic.AtomicInteger;

public class Zeitmessung {
    private AtomicInteger integer;

    public void objekterzeugung() {
        integer = new AtomicInteger(integer.get() + 1);
    }

    public void zeit(int iterationen) {
        integer = new AtomicInteger(0);
        long t0 = System.nanoTime();
        for (int i = 0; i < iterationen; i++) {
            objekterzeugung();
        }
        long t1 = System.nanoTime();
        if (integer.get() == iterationen) {
            System.out.println("Eine Objekterzeugung kostet: " + (t1 - t0) / (double) iterationen + " ns");
        }
    }

    public static void main(String[] args) {
        Zeitmessung zeitmessung = new Zeitmessung();
        zeitmessung.zeit(10000);
        zeitmessung.zeit(1000000);
        zeitmessung.zeit(100000);
    }
}

Eine Objekterzeugung kostet: 264.4 ns
Eine Objekterzeugung kostet: 34.967199 ns
Eine Objekterzeugung kostet: 42.734 ns

Wie du siehst, sind die Schwankungen bereits hier enorm. Ich vermute dass bereits hier optimiert wird.

Wiederholst du jetzt immer bereits gegebene Antworten?

Was soll die Provokation?

 

[Robert Zenz]

Was soll die Provokation?

Die Frage ist doch: Fuegt dein erster Beitrag noch etwas brauchbares zum Thema hinzu oder ist er nur Rauschen? Direkt mit dem zweiten zu Antworten waere besser.

Wie du siehst, sind die Schwankungen bereits hier enorm. Ich vermute dass bereits hier optimiert wird.

Ich vermute dass 1 Million Iterationen einfach zu wenig sind um eine Operation zu messen welche wahrscheinlich ~20 CPU Operationen lang ist, wenn ueberhaupt.

 

[ing0-bing0]

Ich vermute dass 1 Million Iterationen einfach zu wenig sind um eine Operation zu messen welche wahrscheinlich ~20 CPU Operationen lang ist, wenn ueberhaupt.

Nö, ich vermute, dass bereits optimiert wird (Stichworte JIT, Hotspot)

Die Frage ist doch: Fuegt dein erster Beitrag noch etwas brauchbares zum Thema hinzu oder ist er nur Rauschen?

Gut, dass du genau weißt, was nur "Rauschen" ist.

 

[blz]

Vielen Dank für die Antworten!
Mir ist nur noch nicht klar, warum meine Ausgaben immer ein Vielfaches von 100 sind?
Kann mir das noch jmd erklären? (Oder habe ich etwas nicht verstanden?)

 

[fhoffmann]

Das ist doch in der Dokumentation beschrieben:
"This method provides nanosecond precision, but not necessarily nanosecond resolution (that is, how frequently the value changes) - no guarantees are made except that the resolution is at least as good as that of currentTimeMillis()."

 

[Oneixee5]

Abgesehen von den Hinweisen in den anderen Beiträgen und der Doku, tauchen bei mir immer mal wieder völlig krumme Werte auf aber auch viele Gleiche, wenn ich deinen Code mal in der IDE laufen lasse.

Dauer Objekterzeugung (in ns): 978
Dauer Objekterzeugung (in ns): 1396
Dauer Objekterzeugung (in ns): 1885
Dauer Objekterzeugung (in ns): 1466
Dauer Objekterzeugung (in ns): 977
Dauer Objekterzeugung (in ns): 907
Dauer Objekterzeugung (in ns): 1885
Dauer Objekterzeugung (in ns): 4398

Die meiste Leistung dürfte dabei System.out.println benötigen.
Mit einer andern Java-Version (hier: 21.3.0.r17-grl) oder OS kann das aber ganz anders aussehen.

 

[Staarfightaar]

die nanosekunden werden vor dem system.out.println berechnet, warum sollte das einen effekt haben?

 

[Oneixee5]

die nanosekunden werden vor dem system.out.println berechnet, warum sollte das einen effekt haben?

Keinen Effekt auf die Berechnung der Laufzeitmessung aber mehr Last als i++;. Du hast aber Recht, ich hätte den Satz einfach weglassen sollen.