std::cout ist langsam! Stimmt es wirklich? (Ein kleiner Test)

Don06

Hallo,

Oft hört man ja std::cout und Konsorten (std::clog, std::cerr) hätten im direkten Verglich mit std::printf und seinen Abwandlungen keine Chance (zumindest im Bezug auf Schnelligkeit. Dass sie typsicher und erweiterbar sind, ist natürlich ihr großer Vorteil). Genauso oft taucht allerdings das Argument auf, dass std::cout durch ein höheres Maß an Typinformationen eigentlich schneller als std::printf, das zuerst den Formatstring parsen muss, sein müsste.

Zumindest bei meinem Kompiler (VC++ 2008 EE) ist std::cout im Vergleich zu std::printf einfach nur langsam. Ich fragte mich also, woran das liegt. Nachdem ich mir die std::basic_ostream Klasse angesehen hatte, erkannt ich, dass die Typinformationen sehr wohl genutzt wurden. Zur Umwandlung von bestimmten Variablen in Strings wird ein Facet mit aktuellem Locale benutzt.

Was bleibt da noch übrig? Ein eigenes Locale schreiben um herauszufinden, ob das der Flaschenhals ist, war mir zu aufwendig. Außerdem zeigten kleine Profilingtests das die meiste Zeit in den Methoden des internen Streambuffers verwendet wurde. Folglich arbeitete ich mich ein wenig in Streambuffer ein und habe eine eigene ConsoleBuffer Klasse geschrieben, die auf OS-spezifischen Funktionen beruht (Ich wollte ein schnelles std::cout erschaffen). Da ich nur Windows habe, benutzt mein Buffer intern WriteConsole.

Letzten Endes war das einfügen des Buffers in std::cout dann eine Kleinigkeit:

std::cout.rdbuf(&console_buffer)

Daraufhin folgte ein kleines Benchmark. Ich habe std::cout mit normalem Puffer, std::printf, std::puts und std::cout mir meinem Puffer verglichen. Erwartet hatte ich ungefähr Folgendes:

4. std::cout (normal)
3. std::cout (mein Puffer)
2. std::printf
1. std::puts

Ich erhoffte mir einen kleinen Vorsprung vor dem normalen Puffer. std::puts hielt ich für schneller als std::printf, da es den String nicht nach Formatzeichen parsen musste.

Die tatsächlichen Ergebnisse sind aber ein wenig anders. Hier mal ein Ergebnis bei dem ein String mit einer Länge von 247 Zeichen (hat sich so ergeben) 20.000 mal ausgegeben wurde (auf die Konsole):

std::cout (normal Buffer) : 41.968s
std::printf : 1.672s
std::puts : 2.094s
std::cout (dons::ConsoleBuffer): 1.687s

Andere Tests lieferten im Verhältnis gleiche Ergebnisse. Erstaunlich ist, das puts langsamer als das parsende printf ist und das std::cout fast so schnell wie printf ist. Interessant wird es wohl erst, wenn Variablen anderen Typs ausgegeben werden und printf parsen muss. Dafür hatte ich bisjetzt aber leider noch keine Zeit.

Den Geschwindigkeitsunterschied zwischen den verschiedenen Puffern führe ich momentan auf die Thread-Sicherheit des normalen Puffers zurück. Einen so großen Unterschied (Faktor ca. 25) hatte ich allerdings nicht erwartet. Ist zwar jetzt Implementationsabhängig, aber, wenn jemand den Grund hierfür kennt, bin ich immer daran interessiert.

Wenn jemand Interesse an dem Code hat, stelle ich ihn hier gerne rein (zu finden hier). Auch Kritik ist dann natürlich erwünscht, da ich davon ausgehe, dass ich irgendwo grobe Fehler gemacht habe, die irgendwann zu undefiniertem Verhalten führen oder nicht einem Standard Streambuffer gerecht werden, usw.

Gruß
Don06

phlox81

Denke dein Testprogrammcode währe noch interessant.
Dann könnte man auch optimieren

GNU-Fan

Don06 schrieb:

Wenn jemand Interesse an dem Code hat, stelle ich ihn hier gerne rein. Auch Kritik ist dann natürlich erwünscht, da ich davon ausgehe, dass ich irgendwo grobe Fehler gemacht habe, die irgendwann zu undefiniertem Verhalten führen oder nicht einem Standard Streambuffer gerecht werden, usw.

Selbstverständlich musst du dein Testprogramm mitangeben, wenn du hier Benchmarkergebnisse veröffentlichst.

Wie soll man es denn sonst kontrollieren bzw. auf anderen Implementierungen testen?

funky cat

Don06 schrieb:

Erstaunlich ist, das puts langsamer als das parsende printf ist...

Anscheinend schreibt puts den String direkt zum Ausgabegerät und wartet auf eine Rückmeldung, bevor der nächste String gesendet werden kann. Printf formatiert die Ausgabe erstmal im Speicher (Pufferung, Daten sammeln) und braucht daher viel weniger Schreibzugriffe zur Hardware. Das wäre vielleicht eine Erklärung.

Don06

Hier gibt es die Sources. Es fehlt noch jegliche Dokumentation und ein bisschen müsste man wohl noch überarbeiten, aber das seht ihr dann selbst.

@funky cat: Danke, das wäre dann natürlich logisch.

Gruß
Don06

queer_boy

hm - also ich hab dein program ausprobiert, allerdings den teil mit deinem streambuf weggelassen (unter linux) und NUMBER_OF_PRINTS auf 50000 verzehnfacht, weil die ausgabe sonst <0.02 sekunden war, ergebnis:

g++ (4.2.2) -Wall
std::cout (normal Buffer)      : 0.17s
std::printf                    : 0.38s
std::puts                      : 0.34s

dazu muss ich fairerweise sagen, dass der flaschenhals allein darin liegt, wie schnell meine konsole den text anzeigen kann:

time -p ./main
std::cout (normal Buffer)      : 0.17s
std::printf                    : 0.38s
std::puts                      : 0.33s

real 17.24
user 0.16
sys 0.72

dabei komme ich mit gnome-terminal also auf 17.24 sekunden, das fast dreimal schneller ist als xterm (58.10s).

jetzt der direkte vergleich mit folgender änderung am programm:

#ifndef TEST
#error "define TEST!"
#endif 

int main()

{

	std::cout.sync_with_stdio(false);

	double times[4];

   times[TEST] = make_test(TEST);

	const char* const TEST_NAMES[] =

		{ "std::cout (normal Buffer)      ", 

		  "std::printf                    ", 

		  "std::puts                      " };

	std::cout << '\n' << std::endl;

   std::cout << TEST_NAMES[TEST] << ": " << times[TEST] << 's' << std::endl;

	return 0;

}

die ergebnisse (gnome-terminal):

g++ -Wall -DTEST=0 -o testcout
g++ -Wall -DTEST=1 -o testprintf
g++ -Wall -DTEST=2 -o testputs

time -p ./testcout

std::cout (normal Buffer)      : 0.17s
real 5.43
user 0.01
sys 0.16

time -p ./testprintf

std::printf                    : 0.36s
real 6.17
user 0.09
sys 0.27

time -p ./testputs

std::puts                      : 0.36s
real 5.91
user 0.04
sys 0.32

der flaschenhals liegt also eindeutig bei der jeweiligen konsole, die ich verwendet habe. die zeit, die cout, printf oder puts selbst brauchen, ist vernachlässigbar.
warum deine implementation des cout-streambufs so langsam ist, kann dir wohl am besten die dokumentation deiner entwicklungsumgebung sagen (threadsafe? anderer overhead? funktionalität? vergessen, auf release zu schalten?)

abgesehen davon finde ich nicht, dass man bei einer text-ausgabe auf die geschwindigkeit achten sollte; ich habe zumindest noch niemanden gesehen, der 50000 wörter in fünf millisekunden lesen kann.

std::endl ist überflüssig.