Warum ist das Drucken auf Standard so langsam? Kann es beschleunigt werden?

166

Ich war immer erstaunt / frustriert darüber, wie lange es dauert, einfach mit einer Druckanweisung an das Terminal auszugeben. Nach einigen kürzlich schmerzhaft langsamen Protokollierungen entschied ich mich, mich damit zu befassen, und war ziemlich überrascht, dass fast die gesamte aufgewendete Zeit darauf wartet, dass das Terminal die Ergebnisse verarbeitet.

Kann das Schreiben an stdout irgendwie beschleunigt werden?

Ich habe ein Skript geschrieben (' print_timer.py' am Ende dieser Frage), um das Timing beim Schreiben von 100.000 Zeilen in stdout, in die Datei und mit stdout zu vergleichen /dev/null. Hier ist das Timing-Ergebnis:

$ python print_timer.py
this is a test
this is a test
<snipped 99997 lines>
this is a test
-----
timing summary (100k lines each)
-----
print                         :11.950 s
write to file (+ fsync)       : 0.122 s
print with stdout = /dev/null : 0.050 s

Beeindruckend. Um sicherzustellen, dass Python nicht hinter den Kulissen etwas tut, wie zu erkennen, dass ich stdout zu / dev / null oder so neu zugewiesen habe, habe ich die Umleitung außerhalb des Skripts durchgeführt ...

$ python print_timer.py > /dev/null
-----
timing summary (100k lines each)
-----
print                         : 0.053 s
write to file (+fsync)        : 0.108 s
print with stdout = /dev/null : 0.045 s

Es ist also kein Python-Trick, sondern nur das Terminal. Ich wusste immer, dass das Dumping der Ausgabe in / dev / null die Dinge beschleunigte, aber ich hätte nie gedacht, dass es so wichtig ist!

Es wundert mich, wie langsam die tty ist. Wie kann es sein, dass das Schreiben auf eine physische Festplatte viel schneller ist als das Schreiben auf den "Bildschirm" (vermutlich eine All-RAM-Operation) und effektiv so schnell wie das einfache Abladen in den Müll mit / dev / null?

Dieser Link beschreibt, wie das Terminal E / A blockiert, damit es "[die Eingabe] analysieren, seinen Bildspeicher aktualisieren, mit dem X-Server kommunizieren kann, um durch das Fenster zu scrollen usw." ... aber ich nicht voll verstanden. Was kann so lange dauern?

Ich gehe davon aus, dass es keinen Ausweg gibt (abgesehen von einer schnelleren Implementierung?), Aber ich würde trotzdem fragen.


UPDATE: Nachdem ich einige Kommentare gelesen hatte, fragte ich mich, welchen Einfluss meine Bildschirmgröße tatsächlich auf die Druckzeit hat und welche Bedeutung sie hat. Die wirklich langsamen Zahlen oben sind mit meinem Gnome-Terminal auf 1920x1200 gesprengt. Wenn ich es sehr klein reduziere, bekomme ich ...

-----
timing summary (100k lines each)
-----
print                         : 2.920 s
write to file (+fsync)        : 0.121 s
print with stdout = /dev/null : 0.048 s

Das ist sicherlich besser (~ 4x), ändert aber nichts an meiner Frage. Dies fügt meiner Frage nur hinzu , da ich nicht verstehe, warum das Rendern des Terminalbildschirms das Schreiben einer Anwendung auf stdout verlangsamen sollte. Warum muss mein Programm warten, bis das Rendern des Bildschirms fortgesetzt wird?

Sind nicht alle Terminal- / Tty-Apps gleich? Ich muss noch experimentieren. Mir scheint wirklich, dass ein Terminal in der Lage sein sollte, alle eingehenden Daten zu puffern, sie unsichtbar zu analysieren / zu rendern und nur den neuesten Block zu rendern, der in der aktuellen Bildschirmkonfiguration mit einer vernünftigen Bildrate sichtbar ist. Wenn ich also + fsync in ~ 0,1 Sekunden auf die Festplatte schreiben kann, sollte ein Terminal in der Lage sein, denselben Vorgang in dieser Reihenfolge auszuführen (mit möglicherweise ein paar Bildschirmaktualisierungen, während es dies tat).

Ich hoffe immer noch, dass es eine tty-Einstellung gibt, die von der Anwendungsseite aus geändert werden kann, um dieses Verhalten für Programmierer zu verbessern. Wenn es sich ausschließlich um ein Problem mit der Terminalanwendung handelt, gehört dies möglicherweise nicht einmal zu StackOverflow?

Was vermisse ich?


Hier ist das Python-Programm, mit dem das Timing generiert wird:

import time, sys, tty
import os

lineCount = 100000
line = "this is a test"
summary = ""

cmd = "print"
startTime_s = time.time()
for x in range(lineCount):
    print line
t = time.time() - startTime_s
summary += "%-30s:%6.3f s\n" % (cmd, t)

#Add a newline to match line outputs above...
line += "\n"

cmd = "write to file (+fsync)"
fp = file("out.txt", "w")
startTime_s = time.time()
for x in range(lineCount):
    fp.write(line)
os.fsync(fp.fileno())
t = time.time() - startTime_s
summary += "%-30s:%6.3f s\n" % (cmd, t)

cmd = "print with stdout = /dev/null"
sys.stdout = file(os.devnull, "w")
startTime_s = time.time()
for x in range(lineCount):
    fp.write(line)
t = time.time() - startTime_s
summary += "%-30s:%6.3f s\n" % (cmd, t)

print >> sys.stderr, "-----"
print >> sys.stderr, "timing summary (100k lines each)"
print >> sys.stderr, "-----"
print >> sys.stderr, summary
Russ
quelle
9
Der gesamte Zweck des Schreibens an stdout besteht darin, dass ein Mensch die Ausgabe lesen kann. Kein Mensch auf der Welt kann in 12 Sekunden 10.000 Textzeilen lesen. Was bringt es also, stdout schneller zu machen?
Seun Osewa
14
@Seun Osewa: Ein Beispiel (die meine Frage trieb) ist , wenn Dinge wie tun print - Anweisung Debuggen . Sie möchten Ihr Programm ausführen und die Ergebnisse sehen, sobald sie eintreten. Sie haben offensichtlich Recht, dass die meisten Zeilen vorbeifliegen, die Sie nicht sehen können, aber wenn eine Ausnahme auftritt (oder Sie die von Ihnen sorgfältig platzierte bedingte Anweisung getch / raw_input / sleep treffen), möchten Sie die Druckausgabe direkt betrachten und nicht ständig eine Dateiansicht öffnen oder aktualisieren müssen.
Russ
3
Das Debuggen von Druckanweisungen ist einer der Gründe, warum tty-Geräte (dh Terminals) standardmäßig Zeilenpufferung anstelle von Blockpufferung verwenden: Die Debug-Ausgabe ist nicht sehr nützlich, wenn das Programm hängt und sich die letzten Zeilen der Debug-Ausgabe noch in einem Puffer befinden statt zum Terminal gespült.
Stephen C. Steel
@ Stephen: Aus diesem Grund habe ich mich nicht sehr darum gekümmert, die enormen Verbesserungen zu verfolgen, die ein Kommentator durch Erhöhen der Puffergröße behauptet hat. Es macht den Zweck des Debug-Drucks völlig zunichte! Ich habe während der Untersuchung ein wenig experimentiert, aber keine Nettoverbesserung festgestellt. Ich bin immer noch neugierig auf die Diskrepanz, aber nicht wirklich.
Russ
Manchmal drucke ich bei Programmen mit sehr langer Laufzeit nur alle n Sekunden die aktuelle Zeile aus - ähnlich wie bei einer Aktualisierungsverzögerung in einer Fluch-App. Es ist nicht perfekt, gibt aber eine Vorstellung davon, wo ich ab und zu bin.
Rkulla

Antworten:

155

Wie kann es sein, dass das Schreiben auf eine physische Festplatte viel schneller ist als das Schreiben auf den "Bildschirm" (vermutlich eine All-RAM-Operation) und effektiv so schnell wie das einfache Abladen in den Müll mit / dev / null?

Herzlichen Glückwunsch, Sie haben gerade die Bedeutung der E / A-Pufferung entdeckt. :-)

Die Festplatte scheint schneller zu sein, da sie stark gepuffert ist: Alle Python- write()Aufrufe werden zurückgegeben, bevor tatsächlich etwas auf die physische Festplatte geschrieben wird. (Das Betriebssystem erledigt dies später und kombiniert viele tausend einzelne Schreibvorgänge zu großen, effizienten Blöcken.)

Das Terminal, andererseits wenig oder keine Pufferung: Jeder einzelne print/ write(line)wartet auf die volle Schreib (dh Anzeige zu Ausgabegerät) zu vervollständigen.

Um den Vergleich fair zu gestalten, müssen Sie dafür sorgen, dass der Dateitest dieselbe Ausgabepufferung wie das Terminal verwendet. Dies können Sie tun, indem Sie Ihr Beispiel wie folgt ändern:

fp = file("out.txt", "w", 1)   # line-buffered, like stdout
[...]
for x in range(lineCount):
    fp.write(line)
    os.fsync(fp.fileno())      # wait for the write to actually complete

Ich habe Ihren Dateischreibetest auf meinem Computer ausgeführt und mit Pufferung sind es hier auch 0,05 Sekunden für 100.000 Zeilen.

Mit den obigen Änderungen zum ungepufferten Schreiben dauert es jedoch 40 Sekunden, um nur 1.000 Zeilen auf die Festplatte zu schreiben. Ich habe es aufgegeben, auf 100.000 Zeilen zu warten, aber aus den vorherigen zu extrapolieren, würde es über eine Stunde dauern .

Das relativiert die 11 Sekunden des Terminals, nicht wahr?

Um Ihre ursprüngliche Frage zu beantworten, ist das Schreiben an ein Terminal unter allen Umständen unglaublich schnell, und es gibt nicht viel Raum, um es viel schneller zu machen (aber einzelne Terminals unterscheiden sich in ihrer Arbeit; siehe Russ 'Kommentar dazu Antworten).

(Sie könnten mehr Schreibpufferung hinzufügen, wie bei Festplatten-E / A, aber dann würden Sie erst sehen, was auf Ihr Terminal geschrieben wurde, nachdem der Puffer geleert wurde. Dies ist ein Kompromiss: Interaktivität versus Bulk-Effizienz.)

Pi Delport
quelle
6
Ich bekomme E / A-Pufferung ... Sie haben mich sicherlich daran erinnert, dass ich fsync für einen echten Vergleich der Fertigstellungszeit hätte verwenden sollen (ich werde die Frage aktualisieren), aber ein fsync pro Zeile ist Wahnsinn. Muss ein tty das wirklich effektiv tun? Gibt es keine Terminal- / OS-seitige Pufferung, die für Dateien gleichwertig ist? Das heißt: Anwendungen schreiben in stdout und kehren zurück, bevor das Terminal auf dem Bildschirm angezeigt wird, wobei das Terminal (oder das Betriebssystem) alles puffert. Das Terminal könnte dann den Schwanz sinnvoll mit einer sichtbaren Bildrate auf den Bildschirm übertragen. Das effektive Blockieren in jeder Zeile scheint dumm zu sein. Ich habe das Gefühl, dass mir noch etwas fehlt.
Russ
Sie können einfach einen Griff öffnen, um mit einem großen Puffer selbst zu stdouten, indem Sie so etwas wie verwenden os.fdopen(sys.stdout.fileno(), 'w', BIGNUM). Dies wäre jedoch fast nie nützlich: Fast alle Anwendungen müssten daran denken, nach jeder Zeile der vom Benutzer beabsichtigten Ausgabe explizit zu leeren.
Pi Delport
1
Ich habe früher mit riesigen (bis zu 10 MB fp = os.fdopen(sys.__stdout__.fileno(), 'w', 10000000)) Python-Side-Puffern experimentiert . Die Auswirkung war gleich Null. dh: noch lange tty Verzögerungen. Dies ließ mich denken / erkennen, dass Sie das langsame tty-Problem nur verschieben ... wenn Pythons Puffer schließlich geleert wird, scheint das tty immer noch die gleiche Gesamtverarbeitungsmenge im Stream zu erledigen, bevor Sie zurückkehren.
Russ
8
Beachten Sie, dass diese Antwort irreführend und falsch ist (sorry!). Insbesondere ist es falsch zu sagen, "es gibt nicht viel Raum, um es schneller zu machen [als 11 Sekunden]". Bitte sehen Sie meine eigene Antwort auf die Frage, wo ich zeige, dass das wterm-Terminal das gleiche 11s-Ergebnis in 0,26s erzielt hat.
Russ
2
Russ: Danke für das Feedback! Meiner fdopenMeinung nach hat ein größerer Puffer (2 MB) definitiv einen großen Unterschied gemacht: Die Druckzeit wurde von vielen Sekunden auf 0,05 Sekunden gesenkt, genau wie bei der Dateiausgabe (mit gnome-terminal).
Pi Delport
88

Danke für alle Kommentare! Ich habe es selbst mit Ihrer Hilfe beantwortet. Es fühlt sich jedoch schmutzig an, Ihre eigene Frage zu beantworten.

Frage 1: Warum wird langsam gedruckt?

Antwort: Das Drucken auf Standard ist nicht von Natur aus langsam. Das Terminal, mit dem Sie arbeiten, ist langsam. Und es hat so gut wie nichts mit E / A-Pufferung auf der Anwendungsseite zu tun (z. B. Python-Dateipufferung). Siehe unten.

Frage 2: Kann es beschleunigt werden?

Antwort: Ja, das kann es, aber anscheinend nicht von der Programmseite (die Seite, die das 'Drucken' nach stdout durchführt). Verwenden Sie zur Beschleunigung einen schnelleren anderen Terminalemulator.

Erläuterung...

Ich habe ein selbst beschriebenes "leichtes" Terminalprogramm namens aufgerufen wtermund dabei deutlich bessere Ergebnisse erzielt. Unten ist die Ausgabe meines wtermTestskripts (am Ende der Frage) aufgeführt, wenn es mit 1920 x 1200 auf demselben System ausgeführt wird, auf dem die grundlegende Druckoption mit dem Gnome-Terminal 12 Sekunden gedauert hat:

-----
Timing-Zusammenfassung (jeweils 100.000 Zeilen)
-----
Druck: 0,261 s
In Datei schreiben (+ fsync): 0.110 s
Drucken mit stdout = / dev / null: 0,050 s

0,26s ist VIEL besser als 12s! Ich weiß nicht, ob wtermes intelligenter ist, wie es so dargestellt wird, wie ich es vorgeschlagen habe (den "sichtbaren" Schwanz mit einer angemessenen Bildrate rendern), oder ob es nur "weniger" macht als gnome-terminal. Für die Zwecke meiner Frage habe ich jedoch die Antwort. gnome-terminalist langsam.

Also - Wenn Sie ein lang laufendes Skript haben, das Ihrer Meinung nach langsam ist und riesige Textmengen an stdout spuckt, versuchen Sie es mit einem anderen Terminal und prüfen Sie, ob es besser ist!

Beachten Sie, dass ich ziemlich zufällig wtermaus den Ubuntu / Debian-Repositories gezogen habe. Dieser Link ist möglicherweise dasselbe Terminal, aber ich bin mir nicht sicher. Ich habe keine anderen Terminalemulatoren getestet.


Update: Da ich den Juckreiz kratzen musste, habe ich einen ganzen Stapel anderer Terminalemulatoren mit demselben Skript und Vollbild (1920 x 1200) getestet. Meine manuell gesammelten Statistiken sind hier:

wterm 0,3s
aterm 0,3s
rxvt 0,3s
mrxvt 0,4s
konsole 0.6s
Yakuake 0,7s
lxterminal 7s
xterm 9s
Gnom-Terminal 12s
xfce4-terminal 12s
vala-terminal 18s
xvt 48s

Die aufgezeichneten Zeiten werden manuell erfasst, waren aber ziemlich konsistent. Ich habe den besten (ish) Wert aufgezeichnet. YMMV natürlich.

Als Bonus war es eine interessante Tour durch einige der verschiedenen Terminalemulatoren, die es gibt! Ich bin erstaunt, dass sich mein erster "alternativer" Test als der beste herausgestellt hat.

Russ
quelle
1
Sie können auch versuchen, aterm. Hier sind die Ergebnisse meines Tests mit Ihrem Skript. Aterm - Druck: 0,491 s, Schreiben in Datei (+ fsync): 0,110 s, Drucken mit stdout = / dev / null: 0,087 s wterm - Drucken: 0,521 s, Schreiben in Datei (+ fsync): 0,105 s, Drucken mit stdout = / dev / null: 0,085 s
frogstarr78
1
Wie vergleicht sich urxvt mit rxvt?
Daenyth
3
Außerdem sollte screen(das Programm) in die Liste aufgenommen werden! (Oder byobuein Wrapper für screenVerbesserungen) Dieses Dienstprogramm ermöglicht mehrere Terminals, ähnlich wie Registerkarten in X-Terminals. Ich gehe davon aus, dass das Drucken auf dem aktuellen screenTerminal dasselbe ist wie das Drucken auf einem einfachen Terminal, aber wie sieht es aus, wenn Sie in einem der screenTerminals drucken und dann ohne Aktivität zu einem anderen wechseln?
Armando Pérez Marqués
1
Seltsam, vor einiger Zeit habe ich verschiedene Terminals in Bezug auf Geschwindigkeit verglichen und Gnome-Terminal hat sich in ziemlich ernsthaften Tests am besten bewährt, während xterm am langsamsten war. Vielleicht haben sie seitdem hart an der Pufferung gearbeitet. Auch die Unicode-Unterstützung könnte einen großen Unterschied machen.
Tomas Pruzina
2
iTerm2 unter OSX gab mir : print: 0.587 s, write to file (+fsync): 0.034 s, print with stdout = /dev/null : 0.041 s. Und mit 'Bildschirm' läuft in iTerm2:print: 1.286 s, write to file (+fsync): 0.043 s, print with stdout = /dev/null : 0.033 s
Rkulla
13

Ihre Umleitung bewirkt wahrscheinlich nichts, da Programme bestimmen können, ob ihre Ausgabe-FD auf eine tty zeigt.

Es ist wahrscheinlich, dass stdout zeilengepuffert ist, wenn auf ein Terminal gezeigt wird (dasselbe wie das stdoutStream-Verhalten von C ).

Versuchen Sie als amüsantes Experiment, die Ausgabe an weiterzuleiten cat.


Ich habe mein eigenes amüsantes Experiment ausprobiert und hier sind die Ergebnisse.

$ python test.py 2>foo
...
$ cat foo
-----
timing summary (100k lines each)
-----
print                         : 6.040 s
write to file                 : 0.122 s
print with stdout = /dev/null : 0.121 s

$ python test.py 2>foo |cat
...
$ cat foo
-----
timing summary (100k lines each)
-----
print                         : 1.024 s
write to file                 : 0.131 s
print with stdout = /dev/null : 0.122 s
Hasturkun
quelle
Ich habe nicht daran gedacht, dass Python seine Ausgabe FS überprüft. Ich frage mich, ob Python hinter den Kulissen einen Trick macht. Ich erwarte nicht, aber ich weiß es nicht.
Russ
+1 für den Hinweis auf den entscheidenden Unterschied in der Pufferung
Peter G.
@Russ: die -uOption Kräfte stdin, stdoutund stderrungepufferte zu sein, was langsamer sein wird als Block wird gepuffert (wegen Overhead)
Hasturkun
4

Ich kann nicht über die technischen Details sprechen, weil ich sie nicht kenne, aber das überrascht mich nicht: Das Terminal wurde nicht zum Drucken vieler solcher Daten entwickelt. In der Tat stellen Sie sogar einen Link zu einer Menge GUI-Dingen bereit, die jedes Mal ausgeführt werden müssen, wenn Sie etwas drucken möchten! Beachten Sie pythonw, dass es nicht 15 Sekunden dauert , wenn Sie das Skript stattdessen mit aufrufen . Dies ist ein GUI-Problem. Umleiten stdoutin eine Datei, um dies zu vermeiden:

import contextlib, io
@contextlib.contextmanager
def redirect_stdout(stream):
    import sys
    sys.stdout = stream
    yield
    sys.stdout = sys.__stdout__

output = io.StringIO
with redirect_stdout(output):
    ...
Katriel
quelle
3

Das Drucken auf dem Terminal wird langsam sein. Leider kann ich nicht wirklich sehen, wie Sie dies erheblich beschleunigen würden, wenn Sie keine neue Terminal-Implementierung schreiben.

Shuttle87
quelle
2

Zusätzlich zu der Ausgabe, die wahrscheinlich standardmäßig in einem zeilengepufferten Modus ausgeführt wird, führt die Ausgabe an ein Terminal auch dazu, dass Ihre Daten in ein Terminal und eine serielle Leitung mit maximalem Durchsatz oder in ein Pseudo-Terminal und einen separaten Prozess fließen, der eine Anzeige verarbeitet Ereignisschleife, Rendern von Zeichen aus einer bestimmten Schriftart, Verschieben von Anzeigebits, um eine Bildlaufanzeige zu implementieren. Das letztere Szenario ist wahrscheinlich auf mehrere Prozesse verteilt (z. B. Telnet-Server / Client, Terminal-App, X11-Anzeigeserver), sodass auch Probleme mit der Kontextumschaltung und der Latenz auftreten.

Liudvikas Bukys
quelle
Wahr! Dies veranlasste mich, die Größe meines Terminalfensters (in Gnome) auf etwas Geringes (von 1920 x 1200) zu reduzieren. Sicher genug ... 2,8s Druckzeit vs 11,5s. Viel besser, aber trotzdem ... warum bleibt es stehen? Sie würden denken, der Standardpuffer (hmm) könnte alle 100.000 Zeilen verarbeiten, und die Terminalanzeige würde einfach alles, was auf den Bildschirm passt, vom hinteren Ende des Puffers erfassen und in einem kurzen Schuss erledigen.
Russ
Das xterm (oder in diesem Fall gterm) würde Ihren späteren Bildschirm schneller rendern, wenn es nicht der Meinung wäre, dass es auch alle anderen Ausgaben auf dem Weg anzeigen müsste. Wenn es versuchen würde, diesen Weg zu gehen, würde es wahrscheinlich dazu führen, dass der häufige Fall von kleinen Bildschirmaktualisierungen weniger reaktionsschnell erscheint. Wenn Sie diese Art von Software schreiben, können Sie manchmal damit umgehen, indem Sie verschiedene Modi verwenden und versuchen zu erkennen, wann Sie zu einem kleinen oder einem großen Betriebsmodus wechseln müssen. Sie können cat big_file | tailoder sogar cat big_file | tee big_file.cpy | tailsehr oft für diese Beschleunigung verwenden.
Strategie