Hochgenaue Zeitmessung in C++?



  • Hallo Leute,

    ist es möglich eine hochgenaue Zeitmessung in C++ durchzuführen? Je nach PerformanceCounter sollten ja theoretisch Messungen bis im oberen 3-Stelligen Nanosekundenbereich möglich sein. Ich habe in meinem Programm eine Routine, dessen Ausführungszeit kritisch ist und in der sich jede Mikrosekunde negativ auswirkt. Konkret handelt es sich um ein Zeitprotokoll.

    Dazu erstmal folgender Code, der das Problem verdeutlicht. Im Beispiel wird die Dauer gemessen, in der ein std::vector 100 Werte einfügt:

    #include <iostream>
    #include <vector>
    #include <chrono>
    #include <iomanip>
    #include <thread>
    
    void timeMeasure(int iterations)
    {
    	auto start = std::chrono::high_resolution_clock::now();
    
    	// -------- time to be measured --------
    	for (int i = 1; i <= iterations; i++)
    	{
    		// do something...
    		std::vector<int> vec;
    		for (int i = 1; i <= 100; i++)
    		{
    			vec.push_back(i);
    		}
    	}
    	// -------- time to be measured -------- 
    
    	auto end = std::chrono::high_resolution_clock::now();
    	auto time = end - start;
    	std::chrono::duration<double, std::micro> proccess_time_us = time;
    	double val = (proccess_time_us.count() / iterations);
    
    	std::cout << std::fixed << std::setprecision(3);
    	std::cout << "processing time: " << std::setw(8) << val  << " us \t iterations: " << iterations << "\n";
    }
    
    int main()
    {
    	int num = 4; // 4 Messungen pro Messreihe
    	for (int i = 1; i <= num; i++)
    	{
    		timeMeasure(1); // nur eine Messung
    	}
    
    	std::cout << std::endl;
    	std::this_thread::sleep_for(std::chrono::milliseconds(4000)); // kurz warten
    
    	for (int i = 1; i <= num; i++)
    	{
    		timeMeasure(1);
    	}
    
    	std::cout << std::endl;
    	std::this_thread::sleep_for(std::chrono::milliseconds(4000));
    
    	for (int i = 1; i <= num; i++)
    	{
    		timeMeasure(1);
    	}
    
    	std::cout << std::endl;
    	std::this_thread::sleep_for(std::chrono::milliseconds(4000));
    
    	for (int i = 1; i <= num; i++)
    	{
    		timeMeasure(10000); // 10000 Messungen (Durschschnitt bilden)
    	}
    	std::cout << std::endl;
    	std::this_thread::sleep_for(std::chrono::milliseconds(4000));
    
    	for (int i = 1; i <= num; i++)
    	{
    		timeMeasure(10000);
    	}
    	std::cout << std::endl;
    	std::this_thread::sleep_for(std::chrono::milliseconds(4000));
    
    	for (int i = 1; i <= num; i++)
    	{
    		timeMeasure(10000);
    	}
    
    	std::cout << "\n--------------------\nENDE" << std::endl;
    	std::cin.get();
    	return 0;
    }
    

    Ausgabe:

    processing time:   25.827 us     iterations: 1
    processing time:    4.034 us     iterations: 1
    processing time:    3.103 us     iterations: 1
    processing time:    2.793 us     iterations: 1
    
    processing time:   31.480 us     iterations: 1
    processing time:    4.344 us     iterations: 1
    processing time:    3.413 us     iterations: 1
    processing time:    2.793 us     iterations: 1
    
    processing time:   23.068 us     iterations: 1
    processing time:    4.345 us     iterations: 1
    processing time:    5.896 us     iterations: 1
    processing time:    5.275 us     iterations: 1
    
    processing time:    1.090 us     iterations: 10000
    processing time:    1.032 us     iterations: 10000
    processing time:    1.030 us     iterations: 10000
    processing time:    1.065 us     iterations: 10000
    
    processing time:    1.029 us     iterations: 10000
    processing time:    1.036 us     iterations: 10000
    processing time:    1.027 us     iterations: 10000
    processing time:    1.032 us     iterations: 10000
    
    processing time:    1.013 us     iterations: 10000
    processing time:    1.042 us     iterations: 10000
    processing time:    1.046 us     iterations: 10000
    processing time:    1.040 us     iterations: 10000
    
    --------------------
    ENDE
    

    Im Code messe ich via std::chrono einen bestimmten Code-Abschnitt. In den ersten 3 Messreihen wird 1 Durchlauf vorgenommen (so wie ich es auch machen würde), in den folgenden 3 Messreihen wird der Bereich 10000 durchlaufen und der Druchschnitt gebildet, um Schwankungen zu mitteln. Bei den Einzelmessungen sind die Werte viel höher und die Schwankungen stark ausgeprägt. Insbesondere die erst Messung einer Messreihe ist davon betroffen. Die unteren 3 Messreihen sind hingegen stabil.

    Ich vermute es könnte an den Prozessor liegen der "schläft" und erst aufgewechkt werden muss (ggf. ein Interrupt oder ähnliches). Das Problem habe ich unter Windows (x86); Linux (x86) und Linux (ARM). Unabhängig ob ich VC++17, GCC v6 oder GCC v7 als Compiler verwende oder unterschiedliche Hardware zum Einsatz kommt.

    Wie kann ich die Ausführungszeit zuverlässig messen, wenn ich nur einen Code-Durchlauf messe?

    viele Grüße,
    SBond


  • Mod

    1. Miss Prozessorzeit, nicht Echtzeit! Du willst doch schließlich wissen, wie viel Zeit der Prozessor für deinen Code braucht, nicht ob er zufällig gerade noch was anderes macht (zum Beispiel aufwachen...). Streng genommen misst du nicht einmal Echtzeit, weil nicht definiert ist, ob high_resolution_clock überhaupt 'steady' (im Sinne von steady_clock) ist.

    2. Durchschnitt? Was interessiert dich der Durchschnitt? Deine ersten Messungen zeigen doch schon, dass das Unsinn ist. Hättest du nur einmal gemessen wäre der Durchschnitt ~30µs, bei zwei Messungen ~16µs, bei dreien wäre es ~12µs. Obwohl du aus der zweiten und dritten Messung weißt, dass 2-4µs möglich wären. Das ist doch Unsinn, dann von etwas >10µs auszugehen, bloß weil das der Durchschnitt ist. Nimm das Minimum! (Oder wenn du dich auskennst, nimm ein paar sinnvolle Quantillen der Verteilung)

    3. Das wichtigste: Vergiss 1+2 und nimm stattdessen einen Profiler (und bei Bedarf noch andere Performancetools). Damit wirst du glücklicher.



  • SeppJ schrieb:

    1. Miss Prozessorzeit, nicht Echtzeit! Du willst doch schließlich wissen, wie viel Zeit der Prozessor für deinen Code braucht, nicht ob er zufällig gerade noch was anderes macht (zum Beispiel aufwachen...). Streng genommen misst du nicht einmal Echtzeit, weil nicht definiert ist, ob high_resolution_clock überhaupt 'steady' (im Sinne von steady_clock) ist.

    Ja, Prozessorzeit ist ein gutes Stichwort. ...werde dahingehend mal schauen, ob sich was finden lässt. Ob hier system_clock oder steady_clock verwendet wird, ist tatsächlich nicht definiert. Hätte ich hier im Beispiel natürlich berücksichtigen können.

    SeppJ schrieb:

    2. Durchschnitt? Was interessiert dich der Durchschnitt? Deine ersten Messungen zeigen doch schon, dass das Unsinn ist. Hättest du nur einmal gemessen wäre der Durchschnitt ~30µs, bei zwei Messungen ~16µs, bei dreien wäre es ~12µs. Obwohl du aus der zweiten und dritten Messung weißt, dass 2-4µs möglich wären. Das ist doch Unsinn, dann von etwas >10µs auszugehen, bloß weil das der Durchschnitt ist. Nimm das Minimum!

    Ja. Natürlich ist es Unsinn. Im Produktivsystem kann sowas natürlich nicht gemacht werden. Ob scheinbar 2-4 us drin sind, lässt sich bei den Einzelmessungen kaum sagen, da scheinbar die Messfehler überwiegen. Daher auch die Messung mit dem Durchschnitt. Durch die höhere Messdauer minimiert sich der Messfehler. Daher weisen die unteren 'Messreihen' nur einen geringen jitter auf und eine Dauer von ca 1 us. Die ersten 3 Messreihen bilden aber kein Durschschnitt und erreichen nie die Werte von ca. 1 us bei den Einzelmessungen.

    SeppJ schrieb:

    3. Das wichtigste: Vergiss 1+2 und nimm stattdessen einen Profiler (und bei Bedarf noch andere Performancetools). Damit wirst du glücklicher.

    Jain. Für die Entwicklung ist es tatsächlich die beste Lösung und du hast vollkommen Recht. Für eine Debug-Version möchte ich allerdings während der Laufzeit diese Zeiten messen und protokollieren. Das hatte ich jetzt nicht weiter erwähnt. Mein Fehler.

    Gruß,
    SBond


  • Mod

    SBond schrieb:

    SeppJ schrieb:

    2. Durchschnitt? Was interessiert dich der Durchschnitt? Deine ersten Messungen zeigen doch schon, dass das Unsinn ist. Hättest du nur einmal gemessen wäre der Durchschnitt ~30µs, bei zwei Messungen ~16µs, bei dreien wäre es ~12µs. Obwohl du aus der zweiten und dritten Messung weißt, dass 2-4µs möglich wären. Das ist doch Unsinn, dann von etwas >10µs auszugehen, bloß weil das der Durchschnitt ist. Nimm das Minimum!

    Ja. Natürlich ist es Unsinn. Im Produktivsystem kann sowas natürlich nicht gemacht werden. Ob scheinbar 2-4 us drin sind, lässt sich bei den Einzelmessungen kaum sagen, da scheinbar die Messfehler überwiegen. Daher auch die Messung mit dem Durchschnitt. Durch die höhere Messdauer minimiert sich der Messfehler. Daher weisen die unteren 'Messreihen' nur einen geringen jitter auf und eine Dauer von ca 1 us. Die ersten 3 Messreihen bilden aber kein Durschschnitt und erreichen nie die Werte von ca. 1 us bei den Einzelmessungen.

    Ich glaube, du hast das Argument nicht verstanden. Du willst doch wissen, ob Code A schneller ist als Code B. Das Minimum ist wie schnell der Code ist. Mit dem Durchschnitt erreichst du nicht, dass die Messfehler weggemittelt werden, sondern du holst die ganzen Messfehler überhaupt erst mit rein! Die Messung wird niemals einen kleineren Wert ergeben als den realen Wert, aber sie wird durch allerlei Messfehler etwas zu große Werte ergeben. Das Minimum ist daher deine beste Abschätzung für den realen Wert.



  • Ah ja... Ich hatte dich vermutlich wirklich falsch verstanden. Ich denke das Minimum ist OK. Für konkrete Aussagen (gerade in diesem Zeitbereich) sind Profiler die beste Wahl.

    Danke dir.



  • Weiss nicht. Profiler sind gerade bei kleinen, kurzen Funktionen von denen man bereits weiss dass sie eine "Engstelle" sind mMn. recht wenig hilfreich.



  • kann auch sein, dass er das bei 10000 parallel macht auf einer cpu oder andere Optimierungen. Kann man irgendwie ausstellen.
    Die Zeitmessung selbst könnte auch Zeit dauern. Kannst sie ja mal in die iterations-for reinmachen und danach aufaddieren und am Ende den Durschnitt ausrechnen und schauen, ob da etwas anders raus kommt.

    Für den einfachen Durchlauf generiert er vielleicht beim ersten mal auch erst Strukturen, die dann weiterverwendet werden. Um das warm machen der CPU auszuschließen, kannst ja vor der eigentlichen Funtktion ersteinmal eine dummy Funktion laufen lassen (eine andere) zum warm machen.



  • das warm machen der CPU

    Du meint damit das Hochtakten aus dem idle?



  • Ich glaube dieser Vortrag hier ist wie für dich geschaffen:

    https://www.youtube.com/watch?v=nXaxk27zwlk

    ... besonders wenn du sowas winziges wie std::vector::push_back messen willst (genau darum gehts in dem Vortrag).

    Der Vortrag ist sehr informativ, stellt eine Reihe nützlicher Tools für sowas vor und ist auch noch von jemandem,
    von dem man bei dem Thema durchaus sagen kann, dass er weiß wo sein Handtuch hängt.

    Ausserdem ist es verblüffend zu sehen, was man alles für einen Blödsinn messen kann, wenn man sich an
    solchen Micro-Benchmarks versucht 😉


Log in to reply