Pourquoi l'impression sur stdout est-elle si lente? Peut-il être accéléré?

J'ai toujours été étonné / frustré par le temps qu'il faut pour simplement sortir sur le terminal avec une instruction d'impression. Après une récente journalisation douloureusement lente, j'ai décidé de l'examiner et j'ai été assez surpris de constater que presque tout le temps passé est à attendre que le terminal traite les résultats.

L'écriture sur stdout peut-elle être accélérée d'une manière ou d'une autre?

J'ai écrit un script (' print_timer.py' au bas de cette question) pour comparer le timing lors de l'écriture de 100k lignes dans stdout, dans un fichier et avec stdout redirigé vers /dev/null. Voici le résultat du timing:

$ 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

Sensationnel. Pour m'assurer que python ne fait pas quelque chose dans les coulisses comme reconnaître que j'ai réaffecté stdout à / dev / null ou quelque chose, j'ai fait la redirection en dehors du script ...

$ 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

Ce n'est donc pas une astuce python, c'est juste le terminal. J'ai toujours su que le dumping de la sortie vers / dev / null accélérait les choses, mais je n'ai jamais pensé que c'était si important!

Je suis étonné de voir à quel point le tty est lent. Comment se fait-il que l'écriture sur le disque physique soit BIEN plus rapide que l'écriture sur «l'écran» (vraisemblablement une opération tout-RAM), et est effectivement aussi rapide que simplement vider à la poubelle avec / dev / null?

Ce lien explique comment le terminal bloquera les E / S afin qu'il puisse "analyser [l'entrée], mettre à jour son frame buffer, communiquer avec le serveur X afin de faire défiler la fenêtre et ainsi de suite" ... mais je ne le fais pas l'obtenir pleinement. Qu'est-ce qui peut prendre si longtemps?

Je pense qu'il n'y a aucun moyen de sortir (à part une implémentation tty plus rapide?) Mais je suppose que je demanderais quand même.

MISE À JOUR: après avoir lu certains commentaires, je me suis demandé quel impact la taille de mon écran avait réellement sur le temps d'impression, et cela a une certaine importance. Les nombres vraiment lents ci-dessus sont avec mon terminal Gnome explosé jusqu'à 1920x1200. Si je le réduis très petit, j'obtiens ...

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

C'est certainement mieux (~ 4x), mais cela ne change pas ma question. Cela ne fait qu'ajouter à ma question car je ne comprends pas pourquoi le rendu de l'écran du terminal devrait ralentir l'écriture d'une application sur stdout. Pourquoi mon programme doit-il attendre que le rendu de l'écran se poursuive?

Toutes les applications de terminal / tty ne sont-elles pas créées égales? Je n'ai pas encore expérimenté. Il me semble vraiment qu'un terminal devrait être capable de mettre en mémoire tampon toutes les données entrantes, de les analyser / les rendre de manière invisible et de ne rendre que le morceau le plus récent qui est visible dans la configuration actuelle de l'écran à une fréquence d'images raisonnable. Donc, si je peux écrire + fsync sur le disque en ~ 0,1 seconde, un terminal devrait pouvoir effectuer la même opération dans quelque chose de cet ordre (avec peut-être quelques mises à jour d'écran pendant qu'il le faisait).

J'espère toujours qu'il existe un paramètre tty qui peut être modifié du côté de l'application pour améliorer ce comportement pour le programmeur. S'il s'agit strictement d'un problème d'application de terminal, cela n'appartient peut-être même pas à StackOverflow?

Qu'est-ce que je rate?

Voici le programme python utilisé pour générer le timing:

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

Comment se fait-il que l'écriture sur le disque physique soit BIEN plus rapide que l'écriture sur «l'écran» (vraisemblablement une opération tout-RAM), et est effectivement aussi rapide que de simplement vider la poubelle avec / dev / null?

Félicitations, vous venez de découvrir l'importance de la mise en mémoire tampon d'E / S. :-)

Le disque semble être plus rapide, car il est hautement tamponné: tous les write()appels de Python reviennent avant que quoi que ce soit ne soit réellement écrit sur le disque physique. (Le système d'exploitation fait cela plus tard, combinant plusieurs milliers d'écritures individuelles en un gros morceaux efficaces.)

Le terminal, par contre, ne fait que peu ou pas de mise en mémoire tampon: chaque individu print/ write(line)attend que l' écriture complète (c'est-à-dire l'affichage vers le périphérique de sortie) se termine.

Pour rendre la comparaison équitable, vous devez faire en sorte que le test de fichier utilise le même tampon de sortie que le terminal, ce que vous pouvez faire en modifiant votre exemple en:

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

J'ai exécuté votre test d'écriture de fichier sur ma machine, et avec la mise en mémoire tampon, il est également 0,05 s ici pour 100 000 lignes.

Cependant, avec les modifications ci-dessus pour écrire sans tampon, il faut 40 secondes pour écrire seulement 1 000 lignes sur le disque. J'ai renoncé à attendre 100 000 lignes pour écrire, mais en extrapolant à partir de la précédente, cela prendrait plus d'une heure .

Cela met en perspective les 11 secondes du terminal, n'est-ce pas?

Donc, pour répondre à votre question initiale, écrire sur un terminal est en fait incroyablement rapide, tout bien considéré, et il n'y a pas beaucoup de place pour le rendre beaucoup plus rapide (mais les terminaux individuels varient dans la quantité de travail qu'ils effectuent; voir le commentaire de Russ à ce sujet. répondre).

(Vous pouvez ajouter plus de tampon d'écriture, comme avec les E / S de disque, mais vous ne verrez pas ce qui a été écrit sur votre terminal tant que le tampon n'a pas été vidé. C'est un compromis: interactivité contre efficacité en bloc.)

Merci pour tous vos commentaires! J'ai fini par y répondre moi-même avec votre aide. Cela semble sale de répondre à votre propre question.

Question 1: Pourquoi l'impression sur stdout est-elle lente?

Réponse: L' impression sur stdout n'est pas intrinsèquement lente. C'est le terminal avec lequel vous travaillez qui est lent. Et cela n'a pratiquement aucun rapport avec la mise en mémoire tampon des E / S du côté de l'application (par exemple: la mise en mémoire tampon des fichiers python). Voir ci-dessous.

Question 2: Peut-il être accéléré?

Réponse: Oui, c'est possible, mais apparemment pas du côté du programme (le côté faisant «l'impression» vers la sortie standard). Pour l'accélérer, utilisez un autre émulateur de terminal plus rapide.

Explication...

J'ai essayé un programme de terminal «léger» auto-décrit appelé wtermet j'ai obtenu des résultats nettement meilleurs. Vous trouverez ci-dessous la sortie de mon script de test (au bas de la question) lors de l'exécution wtermà 1920x1200 sur le même système où l'option d'impression de base prenait 12s en utilisant gnome-terminal:

-----
résumé du timing (100 000 lignes chacun)
-----
impression: 0,261 s
écrire dans un fichier (+ fsync): 0,110 s
imprimer avec stdout = / dev / null: 0,050 s

0.26s est BEAUCOUP mieux que 12s! Je ne sais pas s'il wtermest plus intelligent sur la façon dont il rend l'écran le long de la façon dont je suggérais (rendre la queue «visible» à une fréquence d'images raisonnable), ou s'il "fait moins" que gnome-terminal. Pour les besoins de ma question, j'ai cependant la réponse. gnome-terminalest lent.

Donc - Si vous avez un script long qui vous semble lent et qu'il crache des quantités massives de texte vers stdout ... essayez un autre terminal et voyez si c'est mieux!

Notez que j'ai tiré à peu près au hasard wtermdes dépôts ubuntu / debian. Ce lien peut être le même terminal, mais je ne suis pas sûr. Je n'ai testé aucun autre émulateur de terminal.

Mise à jour: Parce que je devais gratter la démangeaison, j'ai testé toute une pile d'autres émulateurs de terminaux avec le même script et plein écran (1920x1200). Mes statistiques collectées manuellement sont ici:

wterm 0,3 s
aterm 0,3 s
rxvt 0,3 s
mrxvt 0.4s
konsole 0.6s
yakuake 0.7s
lxterminal 7s
xterm 9s
gnome-terminal 12s
xfce4-terminal 12s
vala-terminal 18s
xvt 48s

Les temps enregistrés sont collectés manuellement, mais ils étaient assez cohérents. J'ai enregistré la meilleure valeur (ish). YMMV, évidemment.

En prime, c'était une visite intéressante de certains des différents émulateurs de terminaux disponibles! Je suis étonné que mon premier test «alternatif» s'est avéré être le meilleur du groupe.

Votre redirection ne fait probablement rien car les programmes peuvent déterminer si leur FD de sortie pointe vers un tty.

Il est probable que stdout soit mis en tampon en ligne lorsqu'il pointe vers un terminal (le même que le stdoutcomportement de flux de C ).

Comme expérience amusante, essayez de diriger la sortie vers cat.

J'ai essayé ma propre expérience amusante, et voici les résultats.

$ 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

Je ne peux pas parler des détails techniques parce que je ne les connais pas, mais cela ne me surprend pas: le terminal n'a pas été conçu pour imprimer beaucoup de données comme celle-ci. En effet, vous fournissez même un lien vers un tas de trucs GUI qu'il doit faire chaque fois que vous voulez imprimer quelque chose! Notez que si vous appelez le script avec à la pythonwplace, cela ne prend pas 15 secondes; c'est entièrement un problème d'interface graphique. Redirigez stdoutvers un fichier pour éviter cela:

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):
    ...

L'impression vers le terminal va être lente. Malheureusement, à moins d'écrire une nouvelle implémentation de terminal, je ne vois pas vraiment comment vous pourriez accélérer cela de manière significative.

En plus de la sortie probablement par défaut en mode tampon de ligne, la sortie vers un terminal entraîne également le flux de vos données vers un terminal et une ligne série avec un débit maximal, ou un pseudo-terminal et un processus séparé qui gère un affichage boucle d'événement, rendu des caractères d'une police, déplacement des bits d'affichage pour implémenter un affichage défilant. Ce dernier scénario est probablement réparti sur plusieurs processus (par exemple, serveur / client telnet, application de terminal, serveur d'affichage X11), il y a donc également des problèmes de changement de contexte et de latence.