Dlaczego drukowanie na standardowe wyjście jest tak wolne? Czy można to przyspieszyć?

166

Zawsze byłem zdumiony / sfrustrowany tym, ile czasu zajmuje po prostu wyprowadzenie na terminal z instrukcją print. Po niedawnym, boleśnie powolnym logowaniu postanowiłem się temu przyjrzeć i byłem dość zaskoczony, że prawie cały czas spędzony na czekaniu, aż terminal przetworzy wyniki.

Czy można w jakiś sposób przyspieszyć pisanie na stdout?

Napisałem skrypt (' print_timer.py' na dole tego pytania), aby porównać czasy podczas zapisywania 100 tys. Wierszy na stdout, do pliku iz przekierowaniem do stdout /dev/null. Oto wynik pomiaru czasu:

$ 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

Łał. Aby upewnić się, że Python nie robi czegoś za kulisami, jak rozpoznawanie, że przypisałem standardowe wyjście do / dev / null lub coś w tym stylu, wykonałem przekierowanie poza skryptem ...

$ 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

Więc to nie jest sztuczka Pythona, to tylko terminal. Zawsze wiedziałem, że zrzucanie danych wyjściowych do / dev / null przyspiesza działanie, ale nigdy nie sądziłem, że jest to aż tak istotne!

Zadziwia mnie, jak powolny jest tty. Jak to możliwe, że zapisywanie na dysku fizycznym jest DUŻO szybsze niż zapisywanie na "ekranie" (przypuszczalnie operacja all-RAM) i jest tak samo szybkie, jak po prostu zrzucanie do śmieci za pomocą / dev / null?

To łącze mówi o tym, jak terminal będzie blokował I / O, aby mógł "analizować [wejście], aktualizować bufor ramki, komunikować się z serwerem X w celu przewijania okna i tak dalej" ... ale ja tego nie robię w pełni to zrozum. Co może trwać tak długo?

Spodziewam się, że nie ma wyjścia (poza szybszą implementacją tty?), Ale i tak zapytam.


AKTUALIZACJA: po przeczytaniu kilku komentarzy zastanawiałem się, jak duży wpływ na czas drukowania ma rozmiar mojego ekranu i ma to pewne znaczenie. Naprawdę wolne liczby powyżej dotyczą mojego terminala Gnome wysadzonego do 1920x1200. Jeśli zmniejszę to bardzo małe, otrzymam ...

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

To jest z pewnością lepsze (~ 4x), ale nie zmienia mojego pytania. Dodaje to tylko do mojego pytania, ponieważ nie rozumiem, dlaczego renderowanie ekranu terminala powinno spowolnić pisanie aplikacji na standardowe wyjście. Dlaczego mój program musi czekać na kontynuację renderowania ekranu?

Czy wszystkie aplikacje terminala / tty nie są sobie równe? Ja jeszcze nie eksperymentowałem. Naprawdę wydaje mi się, że terminal powinien być w stanie buforować wszystkie przychodzące dane, analizować / renderować je w niewidoczny sposób i renderować tylko najnowszy fragment, który jest widoczny w bieżącej konfiguracji ekranu z rozsądną liczbą klatek na sekundę. Więc jeśli mogę napisać + fsync na dysk w ~ 0,1 sekundy, terminal powinien być w stanie wykonać tę samą operację w czymś w tej kolejności (może z kilkoma aktualizacjami ekranu, gdy to robił).

Nadal mam nadzieję, że istnieje ustawienie tty, które można zmienić po stronie aplikacji, aby poprawić to zachowanie dla programisty. Jeśli jest to wyłącznie problem z aplikacją terminalową, to może nawet nie należy do StackOverflow?

czego mi brakuje?


Oto program w Pythonie używany do generowania synchronizacji:

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
źródło
9
Cały cel pisania na stdout polega na tym, aby człowiek mógł odczytać wyjście. Żaden człowiek na świecie nie jest w stanie przeczytać 10 000 wierszy tekstu w 12 sekund, więc jaki jest sens przyspieszenia standardowego wyjścia ???
Seun Osewa
14
@Seun Osewa: Jeden z przykładów (który zadał mi pytanie) dotyczy takich rzeczy, jak debugowanie instrukcji print . Chcesz uruchomić swój program i zobaczyć wyniki na bieżąco. Oczywiście masz rację, że większość linii przeleci obok tego, czego nie widzisz, ale kiedy zdarzy się wyjątek (lub trafisz na warunkową instrukcję getch / raw_input / sleep, którą ostrożnie umieściłeś), chcesz patrzeć bezpośrednio na wynik wydruku, a nie ciągłe otwieranie lub odświeżanie widoku pliku.
Russ
3
Debugowanie instrukcji print jest jednym z powodów, dla których urządzenia tty (tj. Terminale) domyślnie korzystają z buforowania linii zamiast buforowania bloków: wyjście debugowania nie jest zbyt przydatne, jeśli program się zawiesza, a kilka ostatnich wierszy danych debugowania nadal znajduje się w buforze zamiast spłukiwać do terminala.
Stephen C. Steel
@Stephen: Dlatego nie przejmowałem się zbytnio realizacją ogromnych ulepszeń, o których mówił jeden z komentatorów, zwiększając rozmiar bufora. Całkowicie przeczy celowi drukowania debugowania! Podczas badania trochę poeksperymentowałem, ale nie zauważyłem żadnej poprawy. Nadal jestem ciekawy tej rozbieżności, ale nie do końca.
Russ
Czasami w przypadku bardzo długo działających programów po prostu drukuję bieżące standardowe wyjście wiersza co n sekund - podobnie jak w przypadku opóźnienia odświeżania w aplikacji curses. Nie jest idealne, ale daje wyobrażenie o tym, gdzie jestem od razu na jakiś czas.
rkulla

Odpowiedzi:

155

Jak to możliwe, że zapisywanie na dysku fizycznym jest DUŻO szybsze niż zapisywanie na "ekranie" (przypuszczalnie operacja all-RAM) i jest tak samo szybkie, jak po prostu zrzucanie do śmieci za pomocą / dev / null?

Gratulacje, właśnie odkryłeś znaczenie buforowania we / wy. :-)

Dysk wydaje się być szybszy, ponieważ jest silnie buforowany: wszystkie write()wywołania Pythona powracają, zanim cokolwiek zostanie zapisane na dysku fizycznym. (System operacyjny robi to później, łącząc wiele tysięcy pojedynczych zapisów w duże, wydajne fragmenty).

Z drugiej strony terminal wykonuje niewielkie lub żadne buforowanie: każda osoba print/ write(line)czeka na zakończenie pełnego zapisu (tj. Wyświetlania na urządzeniu wyjściowym).

Aby porównanie było sprawiedliwe, musisz sprawić, by test pliku używał tego samego buforowania wyjścia co terminal, co możesz zrobić, modyfikując swój przykład na:

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

Uruchomiłem twój test zapisu plików na moim komputerze i przy buforowaniu, tutaj również wynosi 0,05 s dla 100 000 linii.

Jednak z powyższymi modyfikacjami do zapisu niebuforowanego, zapisanie tylko 1000 linii na dysku zajmuje 40 sekund. Zrezygnowałem z czekania na napisanie 100 000 wierszy, ale ekstrapolując z poprzedniego, zajęłoby to ponad godzinę .

To stawia 11 sekund terminalu w perspektywie, prawda?

Odpowiadając na twoje pierwotne pytanie, pisanie do terminala jest w rzeczywistości niesamowicie szybkie, biorąc pod uwagę wszystkie rzeczy, i nie ma dużo miejsca, aby to zrobić znacznie szybciej (ale poszczególne terminale różnią się ilością wykonywanej pracy; zobacz komentarz Russa na ten temat odpowiedź).

(Możesz dodać więcej buforowania zapisu, tak jak w przypadku dyskowych operacji we / wy, ale wtedy nie zobaczysz, co zostało zapisane na twoim terminalu, dopóki bufor nie zostanie opróżniony. To kompromis: interaktywność a wydajność masowa).

Pi Delport
źródło
6
Dostaję buforowanie I / O ... z pewnością przypomniałeś mi, że powinienem mieć fsync dla prawdziwego porównania czasu ukończenia (zaktualizuję pytanie), ale fsync na linię to szaleństwo. Czy tty naprawdę musi to robić skutecznie? Czy nie ma odpowiednika buforowania po stronie terminala / systemu operacyjnego do plików? tj .: Aplikacje zapisują na stdout i wracają przed wyrenderowaniem terminala na ekran, przy czym terminal (lub system operacyjny) wszystko buforuje. Terminal mógłby wtedy rozsądnie renderować ogon na ekran z widoczną liczbą klatek na sekundę. Skuteczne blokowanie na każdej linii wydaje się głupie. Czuję, że wciąż czegoś mi brakuje.
Russ
Możesz po prostu samodzielnie otworzyć uchwyt do wyjścia na standardowe wyjście z dużym buforem, używając czegoś takiego jak os.fdopen(sys.stdout.fileno(), 'w', BIGNUM). To prawie nigdy nie byłoby przydatne: prawie wszystkie aplikacje musiałyby pamiętać o jawnym opróżnianiu po każdym wierszu zamierzonego przez użytkownika wyniku.
Pi Delport
1
Wcześniej eksperymentowałem z ogromnymi (do 10 MB z fp = os.fdopen(sys.__stdout__.fileno(), 'w', 10000000)) buforami po stronie Pythona. Wpływ był zerowy. tj .: wciąż duże opóźnienia tty. To sprawiło, że pomyślałem / zdałem sobie sprawę, że po prostu odkładasz problem wolnego tty ... kiedy bufor Pythona w końcu opróżnia tty nadal wydaje się, że wykonuje tę samą całkowitą ilość przetwarzania w strumieniu przed powrotem.
Russ
8
Zauważ, że ta odpowiedź jest myląca i błędna (przepraszam!). W szczególności błędne jest stwierdzenie „nie ma zbyt wiele miejsca na przyspieszenie [niż 11 sekund]”. Zobacz moją własną odpowiedź na pytanie, gdzie pokazuję, że terminal wterm osiągnął ten sam wynik 11s w 0,26s.
Russ
2
Russ: dzięki za informację zwrotną! Z mojej strony większy fdopenbufor (2 MB) zdecydowanie zrobił ogromną różnicę: skrócił czas drukowania z wielu sekund do 0,05 s, tak samo jak wyjście pliku (użycie gnome-terminal).
Pi Delport
88

Dzięki za wszystkie komentarze! Skończyło się na tym, że sam na to odpowiedziałem z twoją pomocą. Jednak odpowiadanie na własne pytanie jest nieprzyjemne.

Pytanie 1: Dlaczego drukowanie na standardowe wyjście jest wolne?

Odpowiedź: Drukowanie na standardowe wyjście nie jest z natury powolne. To terminal, z którym pracujesz, działa wolno. I ma prawie zero wspólnego z buforowaniem we / wy po stronie aplikacji (np. Buforowanie plików w języku Python). Zobacz poniżej.

Pytanie 2: Czy można to przyspieszyć?

Odpowiedź: Tak, ale pozornie nie od strony programu (strona wykonująca „drukowanie” na standardowe wyjście). Aby to przyspieszyć, użyj szybszego innego emulatora terminala.

Wyjaśnienie...

Wypróbowałem opisany przez siebie „lekki” program terminalowy o nazwie wtermi uzyskałem znacznie lepsze wyniki. Poniżej znajduje się wynik mojego skryptu testowego (na dole pytania) podczas uruchamiania w wterm1920x1200 w tym samym systemie, w którym podstawowa opcja drukowania zajęła 12 sekund przy użyciu gnome-terminal:

-----
podsumowanie czasu (po 100 tys. wierszy)
-----
wydruk: 0,261 s
zapisz do pliku (+ fsync): 0,110 s
drukuj z stdout = / dev / null: 0,050 s

0,26 s to DUŻO lepsze niż 12 s! Nie wiem, czy wtermjest bardziej inteligentne, jeśli chodzi o to, jak renderuje się na ekranie zgodnie z tym, jak sugerowałem (renderuj „widoczny” ogon przy rozsądnej liczbie klatek na sekundę), czy po prostu „robi mniej” niż gnome-terminal. Jednak na moje pytanie mam odpowiedź. gnome-terminaljest wolny.

Tak więc - jeśli masz długo działający skrypt, który uważasz za powolny i wypluwa ogromne ilości tekstu na standardowe wyjście ... wypróbuj inny terminal i zobacz, czy jest lepszy!

Zwróć uwagę, że prawie losowo pobierałem wtermz repozytoriów ubuntu / debian. Ten link może być tym samym terminalem, ale nie jestem pewien. Nie testowałem żadnych innych emulatorów terminala.


Aktualizacja: Ponieważ musiałem podrapać swędzenie, przetestowałem cały stos innych emulatorów terminala z tym samym skryptem i pełnym ekranem (1920x1200). Moje ręcznie zebrane statystyki są tutaj:

wterm 0.3s
aterm 0.3s
rxvt 0.3s
mrxvt 0.4s
konsole 0.6s
yakuake 0,7 s
lxterminal 7s
xterm 9s
gnome-terminal 12s
xfce4-zacisk 12s
vala-terminal 18s
XVT 48s

Zarejestrowane czasy są zbierane ręcznie, ale były dość spójne. Zarejestrowałem najlepszą (ish) wartość. YMMV, oczywiście.

Jako bonus, była to interesująca wycieczka po niektórych dostępnych emulatorach terminali! Jestem zdumiony, że mój pierwszy test „alternatywny” okazał się najlepszy ze wszystkich.

Russ
źródło
1
Możesz także spróbować aterm. Oto wyniki mojego testu przy użyciu Twojego skryptu. Aterm - wydruk: 0,491 s, zapis do pliku (+ fsync): 0,110 s, wydruk ze stdout = / dev / null: 0,087 s wterm - wydruk: 0,521 s, zapis do pliku (+ fsync): 0,105 s, wydruk ze standardowym wyjściem = / dev / null: 0,085 s
frogstarr78
1
Jak wypada urxvt w porównaniu do rxvt?
Daenyth
3
Ponadto screen(program) powinien znajdować się na liście! (Lub byobu, co jest opakowaniem dla screenulepszeń) To narzędzie pozwala mieć kilka terminali, podobnie jak zakładki w X-terminalach. Zakładam, że drukowanie na bieżącym screenterminalu jest tym samym, co drukowanie na zwykłym, ale co z drukowaniem w jednym z screenterminali, a następnie przełączeniem się na inny bez żadnej aktywności?
Armando Pérez Marques
1
Dziwne, jakiś czas temu porównywałem różne terminale pod względem szybkości i gnome-terminal wypadł najlepiej w dość poważnych testach, podczas gdy xterm był najwolniejszy. Być może od tego czasu ciężko pracowali nad buforowaniem. Również obsługa Unicode może zrobić dużą różnicę.
Tomas Pruzina,
2
iTerm2 na OSX dał mi: print: 0.587 s, write to file (+fsync): 0.034 s, print with stdout = /dev/null : 0.041 s. I z 'screenem' uruchomionym w iTerm2:print: 1.286 s, write to file (+fsync): 0.043 s, print with stdout = /dev/null : 0.033 s
rkulla
13

Twoje przekierowanie prawdopodobnie nic nie daje, ponieważ programy mogą określić, czy ich wyjściowe FD wskazuje na terminal.

Jest prawdopodobne, że stdout jest buforowane wierszowo, gdy wskazuje na terminal (tak samo jak stdoutzachowanie strumienia C ).

W ramach zabawnego eksperymentu spróbuj przekierować wyjście do cat.


Wypróbowałem własny, zabawny eksperyment i oto wyniki.

$ 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
źródło
Nie przyszło mi do głowy, żeby Python sprawdzał swoje wyjście FS. Zastanawiam się, czy Python robi sztuczkę za kulisami? Nie spodziewam się, ale nie wiem.
Russ
+1 za wskazanie najważniejszej różnicy w buforowaniu
Peter G.
@Russ: THE -usił opcji stdin, stdouti stderrbyć buforowany, która będzie mniejsza niż jest blok buforowane (powodu overhead)
Hasturkun
4

Nie mogę mówić o szczegółach technicznych, ponieważ ich nie znam, ale to mnie nie dziwi: terminal nie został zaprojektowany do drukowania wielu takich danych. Rzeczywiście, podajesz nawet łącze do zbioru elementów graficznego interfejsu użytkownika, które musi on wykonać za każdym razem, gdy chcesz coś wydrukować! Zauważ, że jeśli pythonwzamiast tego wywołasz skrypt za pomocą , nie zajmie to 15 sekund; jest to całkowicie kwestia GUI. Przekieruj stdoutdo pliku, aby tego uniknąć:

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
źródło
3

Drukowanie na terminalu będzie powolne. Niestety, nie mówiąc o napisaniu nowej implementacji terminala, nie wiem, jak można to znacznie przyspieszyć.

czółenko 87
źródło
2

Oprócz wyjścia prawdopodobnie domyślnie ustawionego w trybie buforowanym linii, wyjście do terminala powoduje również przepływ danych do terminala i linii szeregowej z maksymalną przepustowością lub do pseudoterminalu i oddzielnego procesu obsługującego wyświetlacz pętla zdarzeń, renderowanie znaków z jakiejś czcionki, przesuwanie bitów wyświetlania w celu zaimplementowania przewijanego wyświetlacza. Ten drugi scenariusz jest prawdopodobnie rozłożony na wiele procesów (np. Serwer / klient telnet, aplikacja terminalowa, serwer wyświetlania X11), więc występują również problemy z przełączaniem kontekstu i opóźnieniami.

Liudvikas Bukys
źródło
Prawdziwe! To skłoniło mnie do zmniejszenia rozmiaru okna terminala (w Gnome) do czegoś mizernego (z 1920x1200). Jasne ... czas drukowania 2,8s vs 11,5s. Znacznie lepiej, ale mimo to ... dlaczego się przeciąga? Można by pomyśleć, że bufor stdout (hmm) mógłby obsłużyć wszystkie 100 tys. Linii, a wyświetlacz terminala po prostu przechwyciłby wszystko, co się zmieści na ekranie, od końca bufora i zrobiłby to jednym szybkim strzałem.
Russ
Xterm (lub w tym przypadku gterm) renderowałby twój ostateczny ekran szybciej, gdyby nie sądził, że musi wyświetlać również wszystkie inne dane wyjściowe po drodze. Gdyby spróbował pójść tą drogą, prawdopodobnie powszechny przypadek aktualizacji małych ekranów wydawałby się mniej responsywny. Podczas pisania tego typu oprogramowania czasami można sobie z tym poradzić, mając różne tryby i próbując wykryć, kiedy trzeba przejść do / z trybu małego do trybu zbiorczego. Możesz użyć cat big_file | taillub nawet cat big_file | tee big_file.cpy | tailbardzo często do tego przyspieszenia.
nategoose