Por que a impressão em stdout é tão lenta? Pode ser acelerado?

Sempre fiquei surpreso / frustrado com o tempo que leva para simplesmente enviar para o terminal com uma declaração de impressão. Após um registro lento e doloroso recente, decidi investigar e fiquei surpreso ao descobrir que quase todo o tempo gasto está aguardando o terminal processar os resultados.

A escrita no stdout pode ser acelerada de alguma forma?

Eu escrevi um script (' print_timer.py' na parte inferior desta pergunta) para comparar o tempo ao escrever 100 mil linhas no stdout, no arquivo e com o stdout redirecionado para/dev/null . Aqui está o resultado do tempo:

$ 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

Uau. Para garantir que o python não esteja fazendo algo nos bastidores, como reconhecer que eu redesignei o stdout para / dev / null ou algo assim, fiz o redirecionamento fora do 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

Portanto, não é um truque de python, é apenas o terminal. Eu sempre soube que descarregar a saída para / dev / null acelerava as coisas, mas nunca imaginei que fosse tão significativo!

Me surpreende o quão lento o tty é. Como pode ser que gravar no disco físico é MUITO mais rápido do que gravar na "tela" (presumivelmente uma operação totalmente com RAM) e é tão rápido quanto simplesmente despejar no lixo com / dev / null?

Este link fala sobre como o terminal bloqueará a E / S para que ele possa "analisar [a entrada], atualizar seu buffer de quadros, se comunicar com o servidor X para rolar a janela e assim por diante" ... mas eu não entendi completamente. O que pode demorar tanto?

Espero que não haja saída (com exceção de uma implementação tty mais rápida?), Mas acho que perguntaria assim mesmo.

ATUALIZAÇÃO: depois de ler alguns comentários, me perguntei quanto impacto meu tamanho de tela realmente teria no tempo de impressão e isso tem algum significado. Os números realmente lentos acima estão com o meu terminal Gnome ampliado para 1920x1200. Se reduzi-lo muito pequeno, fico ...

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

Isso é certamente melhor (~ 4x), mas não muda minha pergunta. Isso só aumenta a minha pergunta, pois não entendo por que a renderização da tela do terminal deve diminuir a velocidade de um aplicativo gravando no stdout. Por que meu programa precisa aguardar a renderização da tela para continuar?

Todos os aplicativos terminal / tty não são criados iguais? Eu ainda tenho que experimentar. Parece-me realmente que um terminal deve ser capaz de armazenar em buffer todos os dados recebidos, analisá-los / renderizá-los invisivelmente e renderizar apenas o bloco mais recente que é visível na configuração atual da tela a uma taxa de quadros sensata. Portanto, se eu puder gravar + fsync no disco em ~ 0,1 segundos, um terminal poderá concluir a mesma operação em algo dessa ordem (com talvez algumas atualizações na tela enquanto o fazia).

Eu ainda espero que exista uma configuração tty que possa ser alterada do lado do aplicativo para melhorar esse comportamento para o programador. Se isso for estritamente um problema de aplicativo de terminal, talvez isso nem pertença ao StackOverflow?

o que estou perdendo?

Aqui está o programa python usado para gerar o tempo:

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

Como pode ser que gravar no disco físico é MUITO mais rápido do que gravar na "tela" (presumivelmente uma operação totalmente com RAM) e é tão rápido quanto simplesmente despejar no lixo com / dev / null?

Parabéns, você acabou de descobrir a importância do buffer de E / S. :-)

O disco parece ser mais rápido, porque é altamente armazenado em buffer: todas as write()chamadas do Python retornam antes que qualquer coisa seja realmente gravada no disco físico. (O sistema operacional faz isso mais tarde, combinando milhares de gravações individuais em grandes e eficientes blocos.)

O terminal, por outro lado, faz pouco ou nenhum buffer: cada indivíduo print/ write(line)espera pela gravação completa (por exemplo, exibição no dispositivo de saída) para concluir.

Para tornar a comparação justa, você deve fazer com que o teste de arquivo use o mesmo buffer de saída do terminal, o que você pode fazer modificando seu exemplo para:

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

Eu executei seu teste de gravação de arquivos na minha máquina e, com buffer, ele também 0,05s aqui para 100.000 linhas.

No entanto, com as modificações acima para gravar sem buffer, são necessários 40 segundos para gravar apenas 1.000 linhas no disco. Desisti de esperar por 100.000 linhas para escrever, mas extrapolando do anterior, levaria mais de uma hora .

Isso coloca os 11 segundos do terminal em perspectiva, não é?

Portanto, para responder à sua pergunta original, escrever em um terminal é realmente incrivelmente rápido, considerando todas as coisas, e não há muito espaço para torná-lo muito mais rápido (mas terminais individuais variam em quanto trabalho eles fazem; veja o comentário de Russ sobre isso responda).

(Você pode adicionar mais buffer de gravação, como na E / S do disco, mas não verá o que foi gravado no seu terminal até que o buffer seja liberado. É uma troca: interatividade versus eficiência em massa.)

Obrigado por todos os comentários! Acabei respondendo pessoalmente com sua ajuda. Parece sujo responder à sua própria pergunta, no entanto.

Pergunta 1: Por que a impressão em stdout é lenta?

Resposta: A impressão em stdout não é inerentemente lenta. É o terminal com o qual você trabalha que é lento. E tem praticamente zero a ver com o buffer de E / S no lado do aplicativo (por exemplo: buffer de arquivo python). Ver abaixo.

Pergunta 2: Pode ser acelerado?

Resposta: Sim, pode, mas aparentemente não do lado do programa (o lado que está 'imprimindo' no stdout). Para acelerar, use um emulador de terminal diferente mais rápido.

Explicação...

Tentei um programa de terminal 'leve' auto-descrito chamado wterme obtive resultados significativamente melhores. Abaixo está a saída do meu script de teste (na parte inferior da pergunta) ao executar wterma 1920x1200 no mesmo sistema em que a opção básica de impressão levou 12 segundos usando o gnome-terminal:

-----
resumo de tempo (100 mil linhas cada)
-----
impressão: 0,261 s
gravação no arquivo (+ fsync): 0.110 s
imprimir com stdout = / dev / null: 0.050 s

0.26s é MUITO melhor que 12s! Não sei se wtermé mais inteligente sobre como torna a tela ao longo das linhas de como eu estava sugerindo (renderize a cauda 'visível' a uma taxa de quadros razoável) ou se apenas "faz menos" que gnome-terminal. Para os fins da minha pergunta, eu tenho a resposta, no entanto. gnome-terminalé lento.

Então - Se você tem um script de execução prolongado que considera lento e envia grandes quantidades de texto ao stdout ... tente um terminal diferente e veja se é melhor!

Note que eu peguei aleatoriamente wtermdos repositórios ubuntu / debian. Esse link pode ser o mesmo terminal, mas não tenho certeza. Não testei nenhum outro emulador de terminal.

Atualização: Como tive que coçar a coceira, testei uma pilha inteira de outros emuladores de terminal com o mesmo script e tela cheia (1920x1200). Minhas estatísticas coletadas manualmente estão aqui:

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

Os tempos registrados são coletados manualmente, mas eram bastante consistentes. Eu gravei o melhor valor (ish). YMMV, obviamente.

Como bônus, foi um passeio interessante por alguns dos vários emuladores de terminal disponíveis no mercado! Estou surpreso que meu primeiro teste 'alternativo' tenha sido o melhor do grupo.

Seu redirecionamento provavelmente não faz nada, pois os programas podem determinar se o FD de saída aponta para um tty.

É provável que stdout seja buffer de linha ao apontar para um terminal (o mesmo que o stdoutcomportamento do fluxo de C ).

Como um experimento divertido, tente canalizar a saída para cat.

Eu tentei meu próprio experimento divertido, e aqui estão os resultados.

$ 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

Não posso falar sobre os detalhes técnicos porque não os conheço, mas isso não me surpreende: o terminal não foi projetado para imprimir muitos dados como este. De fato, você ainda fornece um link para um monte de coisas da GUI que ele precisa fazer toda vez que você deseja imprimir algo! Observe que, se você chamar o script pythonw, ele não levará 15 segundos; isso é totalmente um problema da GUI. Redirecione stdoutpara um arquivo para evitar isso:

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

A impressão no terminal será lenta. Infelizmente, antes de escrever uma nova implementação de terminal, não consigo ver como você aceleraria isso significativamente.

Além da saída provavelmente padrão para o modo de buffer de linha, a saída para um terminal também está fazendo com que seus dados fluam para um terminal e uma linha serial com uma taxa de transferência máxima, ou um pseudo-terminal e um processo separado que esteja manipulando uma exibição loop de evento, renderizando caracteres de alguma fonte, movendo bits de exibição para implementar uma exibição de rolagem. O último cenário provavelmente está espalhado por vários processos (por exemplo, servidor / cliente de telnet, aplicativo de terminal, servidor de exibição X11), de modo que também existem problemas de alternância de contexto e latência.