Mengapa pencetakan ke stdout sangat lambat? Bisakah itu dipercepat?

166

Saya selalu kagum / frustrasi dengan berapa lama waktu yang dibutuhkan untuk hanya output ke terminal dengan pernyataan cetak. Setelah beberapa logging lambat lambat baru-baru ini saya memutuskan untuk melihatnya dan cukup terkejut menemukan bahwa hampir semua waktu yang dihabiskan menunggu terminal untuk memproses hasilnya.

Bisakah menulis ke stdout dipercepat entah bagaimana?

Saya menulis sebuah skrip (' print_timer.py' di bagian bawah pertanyaan ini) untuk membandingkan waktu ketika menulis 100k baris ke stdout, ke file, dan dengan stdout dialihkan ke /dev/null. Berikut ini adalah hasil waktunya:

$ 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

Wow. Untuk memastikan python tidak melakukan sesuatu di balik layar seperti mengenali bahwa saya menetapkan ulang stdout ke / dev / null atau sesuatu, saya melakukan pengalihan di luar skrip ...

$ 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

Jadi ini bukan trik python, itu hanya terminal. Saya selalu tahu membuang output ke / dev / null mempercepat, tetapi tidak pernah mengira itu signifikan!

Ini mengejutkan saya betapa lambatnya tty. Bagaimana bisa menulis ke disk fisik adalah CARA yang lebih cepat daripada menulis ke "layar" (mungkin semua-RAM op), dan secara efektif secepat hanya membuang ke sampah dengan / dev / null?

Tautan ini berbicara tentang bagaimana terminal akan memblokir I / O sehingga dapat "mengurai [input], memperbarui buffer frame-nya, berkomunikasi dengan server X untuk menggulir jendela dan sebagainya" ... tapi saya tidak sepenuhnya mendapatkannya. Apa yang bisa memakan waktu lama?

Saya berharap tidak ada jalan keluar (pendeknya implementasi tty yang lebih cepat?) Tetapi saya akan bertanya.


UPDATE: setelah membaca beberapa komentar saya bertanya-tanya seberapa besar dampak ukuran layar saya pada waktu cetak, dan memang ada beberapa signifikansi. Angka-angka yang sangat lambat di atas adalah dengan terminal Gnome saya meledak hingga 1920x1200. Jika saya menguranginya sangat kecil saya dapatkan ...

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

Itu tentu lebih baik (~ 4x), tetapi tidak mengubah pertanyaan saya. Itu hanya menambah pertanyaan saya karena saya tidak mengerti mengapa rendering layar terminal harus memperlambat penulisan aplikasi ke stdout. Mengapa program saya harus menunggu rendering layar untuk melanjutkan?

Apakah semua aplikasi terminal / tty tidak dibuat sama? Saya belum bereksperimen. Menurut saya benar-benar seperti terminal harus dapat buffer semua data yang masuk, parse / render itu tak terlihat, dan hanya membuat potongan terbaru yang terlihat dalam konfigurasi layar saat ini pada frame rate yang masuk akal. Jadi jika saya dapat menulis + fsync ke disk dalam ~ 0,1 detik, terminal harus dapat menyelesaikan operasi yang sama dalam sesuatu dari urutan itu (dengan mungkin beberapa pembaruan layar saat melakukannya).

Saya masih agak berharap ada pengaturan tty yang dapat diubah dari sisi aplikasi untuk membuat perilaku ini lebih baik untuk programmer. Jika ini benar-benar masalah aplikasi terminal, maka ini mungkin bahkan bukan milik StackOverflow?

Apa yang saya lewatkan?


Berikut adalah program python yang digunakan untuk menghasilkan waktu:

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
sumber
9
Seluruh tujuan penulisan ke stdout adalah agar manusia dapat membaca hasilnya. Tidak ada manusia di dunia yang dapat membaca 10.000 baris teks dalam 12 detik, jadi apa gunanya membuat stdout lebih cepat ???
Seun Osewa
14
@ Seun Osewa: Salah satu contoh (yang mendorong pertanyaan saya) adalah ketika melakukan hal-hal seperti debugging pernyataan cetak . Anda ingin menjalankan program Anda dan melihat hasilnya ketika itu terjadi. Anda jelas benar bahwa sebagian besar baris akan terbang dengan yang tidak dapat Anda lihat, tetapi ketika pengecualian terjadi (atau Anda menekan pernyataan getar / raw_input / sleep yang Anda tempatkan dengan hati-hati), Anda ingin melihat hasil cetak secara langsung daripada terus-menerus harus membuka atau menyegarkan tampilan file.
Russ
3
Debugging pernyataan cetak adalah salah satu alasan mengapa perangkat tty (yaitu terminal) default untuk buffer line daripada buffer block: output debug tidak banyak digunakan jika program hang dan beberapa baris terakhir hasil debug masih dalam buffer bukannya memerah ke terminal.
Stephen C. Steel
@Stephen: Inilah sebabnya saya tidak terlalu repot mengejar peningkatan besar yang diklaim oleh seorang komentator dengan menaikkan ukuran buffer. Ini sepenuhnya mengalahkan tujuan pencetakan debug! Saya melakukan percobaan sedikit saat menyelidiki, tetapi tidak melihat peningkatan bersih. Saya masih ingin tahu tentang perbedaan, tetapi tidak juga.
Russ
Terkadang untuk program yang berjalan sangat lama, saya hanya akan mencetak baris saat ini setiap n detik - mirip dengan memiliki penundaan refresh dalam aplikasi kutukan. Itu tidak sempurna, tetapi memberikan ide tentang di mana saya sekaligus.
rkulla

Jawaban:

155

Bagaimana bisa menulis ke disk fisik adalah CARA yang lebih cepat daripada menulis ke "layar" (mungkin semua-RAM op), dan secara efektif secepat hanya membuang ke sampah dengan / dev / null?

Selamat, Anda baru saja menemukan pentingnya buffering I / O. :-)

Disk tampaknya lebih cepat, karena sangat buffer: semua write()panggilan Python kembali sebelum ada sesuatu yang ditulis ke disk fisik. (OS melakukan ini nanti, menggabungkan ribuan individu menulis menjadi potongan besar, efisien.)

Terminal, di sisi lain, melakukan sedikit atau tidak ada buffering: masing-masing individu print/ write(line)menunggu penulisan lengkap (yaitu tampilan ke perangkat keluaran) untuk menyelesaikan.

Untuk membuat perbandingan adil, Anda harus membuat pengujian file menggunakan buffering output yang sama dengan terminal, yang dapat Anda lakukan dengan memodifikasi contoh Anda menjadi:

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

Saya menjalankan tes penulisan file Anda di komputer saya, dan dengan buffering, itu juga 0,05 di sini untuk 100.000 baris.

Namun, dengan modifikasi di atas untuk menulis unbuffered, dibutuhkan 40 detik untuk menulis hanya 1.000 baris ke disk. Saya menyerah menunggu 100.000 baris untuk menulis, tetapi memperkirakan dari sebelumnya, itu akan memakan waktu lebih dari satu jam .

Itu menempatkan 11 detik terminal ke dalam perspektif, bukan?

Jadi untuk menjawab pertanyaan awal Anda, menulis ke terminal sebenarnya sangat cepat, semua hal dipertimbangkan, dan tidak ada banyak ruang untuk membuatnya lebih cepat (tetapi masing-masing terminal bervariasi dalam berapa banyak pekerjaan yang mereka lakukan; lihat komentar Russ untuk ini menjawab).

(Anda dapat menambahkan lebih banyak buffering tulis, seperti dengan disk I / O, tetapi kemudian Anda tidak akan melihat apa yang ditulis ke terminal Anda sampai setelah buffer memerah. Ini pertukaran: interaktivitas versus efisiensi massal.)

Pi Delport
sumber
6
Saya mendapatkan buffering I / O ... Anda tentu mengingatkan saya bahwa saya seharusnya memiliki fsync untuk perbandingan waktu penyelesaian yang sebenarnya (saya akan memperbarui pertanyaan), tetapi fsync per baris adalah kegilaan. Apakah tty benar-benar perlu melakukan itu secara efektif? Apakah tidak ada buffering terminal / sisi os setara dengan untuk file? yaitu: Aplikasi menulis ke stdout dan kembali sebelum terminal menampilkan layar, dengan terminal (atau os) buffering semuanya. Terminal kemudian bisa dengan masuk akal membuat ekor untuk menyaring pada laju bingkai yang terlihat. Memblokir secara efektif pada setiap baris tampaknya konyol. Saya merasa masih kehilangan sesuatu.
Russ
Anda bisa membuka pegangan untuk stdout dengan buffer besar sendiri, menggunakan sesuatu seperti os.fdopen(sys.stdout.fileno(), 'w', BIGNUM). Ini hampir tidak pernah berguna, meskipun: hampir semua aplikasi harus ingat untuk secara otomatis menyiram setelah setiap baris output yang diinginkan pengguna.
Pi Delport
1
Saya bereksperimen sebelumnya dengan fp = os.fdopen(sys.__stdout__.fileno(), 'w', 10000000)buffer sisi python yang besar (hingga 10MB dengan ). Dampaknya nihil. yaitu: penundaan tty masih panjang. Ini membuat saya berpikir / menyadari bahwa Anda hanya menunda masalah tty lambat ... ketika buffer python akhirnya memerah tty tampaknya masih melakukan jumlah total pemrosesan yang sama di sungai sebelum kembali.
Russ
8
Perhatikan bahwa jawaban ini menyesatkan dan salah (maaf!). Khususnya salah untuk mengatakan "tidak ada banyak ruang untuk membuatnya lebih cepat [dari 11 detik]". Silakan lihat jawaban saya sendiri untuk pertanyaan di mana saya menunjukkan bahwa terminal wterm mencapai hasil 11 yang sama dalam 0,26.
Russ
2
Russ: terima kasih atas umpan baliknya! Di pihak saya, fdopenbuffer yang lebih besar (2MB) pasti membuat perbedaan besar: butuh waktu pencetakan turun dari banyak detik menjadi 0,05, sama dengan output file (menggunakan gnome-terminal).
Pi Delport
88

Terima kasih atas semua komentarnya! Saya akhirnya menjawab sendiri dengan bantuan Anda. Rasanya kotor menjawab pertanyaan Anda sendiri.

Pertanyaan 1: Mengapa mencetak ke stdout lambat?

Jawab: Mencetak ke stdout secara inheren tidak lambat. Terminal tempat Anda bekerja lambat. Dan hampir tidak ada hubungannya dengan I / O buffering di sisi aplikasi (mis: buffering file python). Lihat di bawah.

Pertanyaan 2: Bisakah dipercepat?

Jawab: Ya bisa, tetapi sepertinya tidak dari sisi program (sisi melakukan 'pencetakan' ke stdout). Untuk mempercepatnya, gunakan emulator terminal berbeda yang lebih cepat.

Penjelasan...

Saya mencoba program terminal 'ringan' yang disebut sendiri wtermdan mendapat hasil yang jauh lebih baik. Di bawah ini adalah output dari skrip pengujian saya (di bagian bawah pertanyaan) ketika berjalan di wtermpada 1920x1200 di pada sistem yang sama di mana opsi cetak dasar mengambil 12-an menggunakan gnome-terminal:

-----
ringkasan waktu (masing-masing 100rb baris)
-----
cetak: 0,261 dtk
tulis ke file (+ fsync): 0,110 dtk
cetak dengan stdout = / dev / null: 0,050 s

0.26 jauh lebih baik dari 12! Saya tidak tahu apakah wtermlebih pintar tentang bagaimana membuat untuk menyaring sepanjang bagaimana saya menyarankan (membuat ekor 'terlihat' pada frame rate yang masuk akal), atau apakah itu hanya "kurang" dari gnome-terminal. Untuk keperluan pertanyaan saya, saya sudah mendapatkan jawabannya. gnome-terminallambat.

Jadi - Jika Anda memiliki skrip yang berjalan lama yang Anda rasa lambat dan itu memuntahkan sejumlah besar teks ke stdout ... coba terminal yang berbeda dan lihat apakah itu lebih baik!

Perhatikan bahwa saya cukup banyak menarik secara acak wtermdari repositori ubuntu / debian. Tautan ini mungkin terminal yang sama, tetapi saya tidak yakin. Saya tidak menguji emulator terminal lainnya.


Pembaruan: Karena saya harus menggaruk gatal, saya menguji seluruh tumpukan emulator terminal lainnya dengan skrip dan layar penuh yang sama (1920x1200). Statistik saya yang dikumpulkan secara manual ada di sini:

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

Waktu yang direkam dikumpulkan secara manual, tetapi cukup konsisten. Saya mencatat nilai (ish) terbaik. YMMV, jelas.

Sebagai bonus, itu adalah tur yang menarik dari beberapa emulator terminal yang tersedia di luar sana! Saya kagum dengan tes 'pengganti' pertama saya ternyata yang terbaik dari kelompok itu.

Russ
sumber
1
Anda mungkin juga mencoba aterm. Inilah hasil dalam pengujian saya menggunakan skrip Anda. Aterm - print: 0,491 s, tulis ke file (+ fsync): 0,110 s, cetak dengan stdout = / dev / null: 0,087 s wterm - print: 0,521 s, tulis ke file (+ fsync): 0,105 s, cetak dengan stdout = / dev / null: 0,085 s
frogstarr78
1
Bagaimana urxvt dibandingkan dengan rxvt?
Daenyth
3
Juga, screen(program) harus dimasukkan dalam daftar! (Atau byobu, yang merupakan pembungkus screendengan perangkat tambahan) Utilitas ini memungkinkan untuk memiliki beberapa terminal, seperti tab pada terminal X. Saya berasumsi bahwa mencetak ke screenterminal saat ini sama dengan mencetak ke terminal biasa, tetapi bagaimana dengan mencetak di salah satu screenterminal dan kemudian beralih ke terminal lain tanpa aktivitas?
Armando Pérez Marqués
1
Aneh, beberapa waktu lalu saya membandingkan terminal yang berbeda dalam hal kecepatan dan gnome-terminal keluar terbaik dalam tes yang agak serius sementara xterm paling lambat. Mungkin mereka bekerja keras dalam buffering sejak saat itu. Dukungan unicode juga bisa membuat perbedaan besar.
Tomas Pruzina
2
iTerm2 di OSX memberi saya: print: 0.587 s, write to file (+fsync): 0.034 s, print with stdout = /dev/null : 0.041 s. Dan dengan 'layar' berjalan di iTerm2:print: 1.286 s, write to file (+fsync): 0.043 s, print with stdout = /dev/null : 0.033 s
rkulla
13

Pengalihan Anda mungkin tidak melakukan apa-apa karena program dapat menentukan apakah output FD mereka menunjuk ke tty.

Kemungkinan stdout adalah buffer line ketika menunjuk ke terminal (sama dengan stdoutperilaku stream C ).

Sebagai percobaan yang lucu, coba perpipkan hasilnya ke cat.


Saya sudah mencoba eksperimen lucu saya sendiri, dan inilah hasilnya.

$ 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
sumber
Saya tidak memikirkan python memeriksa output FS-nya. Saya ingin tahu apakah python melakukan trik di belakang layar? Saya berharap tidak, tetapi tidak tahu.
Russ
+1 untuk menunjukkan perbedaan yang sangat penting dalam buffering
Peter G.
@Russ: -umemaksa opsi stdin, stdoutdan stderruntuk tidak dibangun, yang akan lebih lambat daripada menjadi buffered blok (karena overhead)
Hasturkun
4

Saya tidak dapat berbicara tentang detail teknis karena saya tidak mengetahuinya, tetapi ini tidak mengejutkan saya: terminal tidak dirancang untuk mencetak banyak data seperti ini. Memang, Anda bahkan memberikan tautan ke banyak hal GUI yang harus dilakukan setiap kali Anda ingin mencetak sesuatu! Perhatikan bahwa jika Anda memanggil skrip pythonw, alih - alih membutuhkan waktu 15 detik; ini sepenuhnya merupakan masalah GUI. Redirect stdoutke file untuk menghindari ini:

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
sumber
3

Pencetakan ke terminal akan lambat. Sayangnya singkat menulis implementasi terminal baru saya tidak bisa benar-benar melihat bagaimana Anda mempercepat ini secara signifikan.

antar jemput87
sumber
2

Selain output yang mungkin default ke mode buffer-line, output ke terminal juga menyebabkan data Anda mengalir ke terminal dan jalur serial dengan throughput maksimum, atau pseudo-terminal dan proses terpisah yang menangani tampilan. loop acara, rendering karakter dari beberapa font, memindahkan bit tampilan untuk mengimplementasikan tampilan gulir. Skenario yang terakhir mungkin tersebar di beberapa proses (misalnya server telnet / klien, aplikasi terminal, server tampilan X11) sehingga ada masalah pengalihan konteks dan latensi juga.

Liudvikas Bukys
sumber
Benar! Ini mendorong saya untuk mencoba mengurangi ukuran jendela terminal saya (di Gnome) menjadi sesuatu yang kecil (dari 1920x1200). Benar saja ... 2,8s waktu cetak vs 11,5s. Jauh lebih baik, tapi tetap saja ... mengapa macet? Anda akan berpikir buffer stdout (hmm) dapat menangani semua 100k garis dan tampilan terminal hanya akan mengambil apa pun yang bisa muat di layar dari ujung ekor buffer dan menyelesaikannya dalam satu tembakan cepat.
Russ
Xterm (atau gterm, dalam hal ini) akan membuat layar Anda lebih cepat jika tidak berpikir bahwa ia harus menampilkan semua output lainnya juga. Jika ingin mencoba rute ini kemungkinan akan membuat kasus umum pembaruan layar kecil tampak kurang responsif. Saat menulis jenis perangkat lunak ini, Anda kadang-kadang dapat mengatasinya dengan memiliki mode yang berbeda dan mencoba mendeteksi kapan Anda perlu pindah ke / dari mode operasi kecil ke massal. Anda dapat menggunakan cat big_file | tailatau bahkan cat big_file | tee big_file.cpy | tailsangat sering untuk mempercepat ini.
nategoose