Por que é iterar um arquivo duas vezes mais rápido do que lê-lo na memória e computar duas vezes?

Question

Estou comparando o seguinte

tail -n 1000000 stdout.log | grep -c '"success": true'
tail -n 1000000 stdout.log | grep -c '"success": false'

com o seguinte

log=$(tail -n 1000000 stdout.log)
echo "$log" | grep -c '"success": true'
echo "$log" | grep -c '"success": false'

e surpreendentemente o segundo leva quase 3 vezes mais que o primeiro. Deveria ser mais rápido, não deveria?

    

Answer 1

Por um lado, o primeiro método chama tail duas vezes, então tem que fazer mais trabalho do que o segundo método que faz isso apenas uma vez. Por outro lado, o segundo método tem que copiar os dados no shell e, em seguida, recuar, portanto, ele precisa fazer mais trabalho do que a primeira versão em que tail é canalizado diretamente para grep . O primeiro método tem uma vantagem extra em uma máquina com vários processadores: grep pode trabalhar em paralelo com tail , enquanto o segundo método é estritamente serializado, primeiro tail e, em seguida, grep .

Portanto, não há razão óbvia para que um seja mais rápido do que o outro.

Se você quiser ver o que está acontecendo, veja o sistema que o shell faz. Tente com diferentes shells também.

strace -t -f -o 1.strace sh -c '
  tail -n 1000000 stdout.log | grep "\"success\": true" | wc -l;
  tail -n 1000000 stdout.log | grep "\"success\": false" | wc -l'

strace -t -f -o 2-bash.strace bash -c '
  log=$(tail -n 1000000 stdout.log);
  echo "$log" | grep "\"success\": true" | wc -l;
  echo "$log" | grep "\"success\": true" | wc -l'

strace -t -f -o 2-zsh.strace zsh -c '
  log=$(tail -n 1000000 stdout.log);
  echo "$log" | grep "\"success\": true" | wc -l;
  echo "$log" | grep "\"success\": true" | wc -l'

Com o método 1, os principais estágios são:

1. tail lê e procura encontrar seu ponto de partida.
2. tail escreve blocos de 4096 bytes que grep lêem tão rapidamente quanto são produzidos.
3. Repita a etapa anterior para a segunda string de pesquisa.

Com o método 2, as principais etapas são:

1. tail lê e procura encontrar seu ponto de partida.
2. tail escreve blocos de 4096 bytes que o bash lê 128 bytes de cada vez, e zsh lê 4096 bytes de cada vez.
3. Bash ou zsh grava trechos de 4096 bytes que grep lêem tão rápido quanto são produzidos.
4. Repita a etapa anterior para a segunda string de pesquisa.

Os trechos de 128 bytes do Bash, ao ler a saída da substituição de comando, a reduzem significativamente; O zsh sai tão rápido quanto o método 1 para mim. Sua milhagem pode variar dependendo do tipo e número da CPU, da configuração do agendador, das versões das ferramentas envolvidas e do tamanho dos dados.

    

Answer 2

Eu fiz o seguinte teste e no meu sistema a diferença resultante é cerca de 100 vezes maior para o segundo script.

Meu arquivo é uma saída strace chamada bigfile

$ wc -l bigfile.log 
1617000 bigfile.log

Scripts

xtian@clafujiu:~/tmp$ cat p1.sh
tail -n 1000000 bigfile.log | grep '"success": true' | wc -l
tail -n 1000000 bigfile.log | grep '"success": false' | wc -l

xtian@clafujiu:~/tmp$ cat p2.sh
log=$(tail -n 1000000 bigfile.log)
echo "$log" | grep '"success": true' | wc -l
echo "$log" | grep '"success": true' | wc -l

Eu não tenho nenhuma correspondência para o grep, então nada é escrito no último canal até wc -l

Aqui estão os horários:

xtian@clafujiu:~/tmp$ time bash p1.sh
0
0

real    0m0.381s
user    0m0.248s
sys 0m0.280s
xtian@clafujiu:~/tmp$ time bash p2.sh
0
0

real    0m46.060s
user    0m43.903s
sys 0m2.176s

Então, eu corri os dois scripts novamente por meio do comando strace

strace -cfo p1.strace bash p1.sh
strace -cfo p2.strace bash p2.sh

Aqui estão os resultados dos traços:

$ cat p1.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.24    0.508109       63514         8         2 waitpid
  1.61    0.008388           0     84569           read
  1.08    0.005659           0     42448           write
  0.06    0.000328           0     21233           _llseek
  0.00    0.000024           0       204       146 stat64
  0.00    0.000017           0       137           fstat64
  0.00    0.000000           0       283       149 open
  0.00    0.000000           0       180         8 close
...
  0.00    0.000000           0       162           mmap2
  0.00    0.000000           0        29           getuid32
  0.00    0.000000           0        29           getgid32
  0.00    0.000000           0        29           geteuid32
  0.00    0.000000           0        29           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         7           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.522525                149618       332 total

E p2.strace

$ cat p2.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 75.27    1.336886      133689        10         3 waitpid
 13.36    0.237266          11     21231           write
  4.65    0.082527        1115        74           brk
  2.48    0.044000        7333         6           execve
  2.31    0.040998        5857         7           clone
  1.91    0.033965           0    705681           read
  0.02    0.000376           0     10619           _llseek
  0.00    0.000000           0       248       132 open
...
  0.00    0.000000           0       141           mmap2
  0.00    0.000000           0       176       126 stat64
  0.00    0.000000           0       118           fstat64
  0.00    0.000000           0        25           getuid32
  0.00    0.000000           0        25           getgid32
  0.00    0.000000           0        25           geteuid32
  0.00    0.000000           0        25           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         6           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    1.776018                738827       293 total

Análise

Não é de surpreender que, em ambos os casos, a maior parte do tempo seja gasta aguardando a conclusão de um processo, mas p2 espera 2,63 vezes mais que p1 e, como outros já mencionaram, você está iniciando tardiamente em p2.sh.

Então, esqueça o waitpid , ignore a coluna % e observe a coluna de segundos nos dois traços.

Maior tempo p1 gasta a maior parte do tempo em leitura provavelmente porque há um arquivo grande para ler, mas p2 gasta 28,82 vezes mais tempo em leitura que p1. - bash não espera ler um arquivo tão grande em uma variável e provavelmente está lendo o buffer de cada vez, dividindo em linhas e, em seguida, obtendo outro.

leitura de leitura p2 é 705k vs 84k para p1, cada leitura requer uma mudança de contexto para o espaço do kernel e para fora novamente. Quase 10 vezes o número de leituras e interruptores de contexto.

Tempo em gravação p2 gasta 41,93 vezes mais tempo em gravação que p1

write count p1 faz mais gravações que p2, 42k vs 21k, no entanto elas são muito mais rápidas.

Provavelmente devido ao echo de linhas em grep em oposição a buffers de gravação de cauda.

Ainda mais , p2 gasta mais tempo em escrita do que em leitura, p1 é o contrário!

Outro fator Veja o número de brk chamadas do sistema: p2 gasta 2,42 vezes mais tempo do que a leitura! Em p1 (nem se registra). brk é quando o programa precisa expandir seu espaço de endereço porque o suficiente não foi alocado inicialmente, isso provavelmente se deve ao fato de ter que ler esse arquivo na variável, e não esperar que ele seja tão grande, e como @scai mencionou , se o arquivo ficar muito grande, mesmo isso não funcionaria.

O

tail é provavelmente um leitor de arquivos bastante eficiente, porque é para isso que ele foi projetado, ele provavelmente faz o mapeamento do arquivo e procura por quebras de linha, permitindo que o kernel otimize o i / o. O bash não não é tão bom tanto no tempo gasto lendo e escrevendo.

p2 gasta 44ms e 41ms em clone e execv não é uma quantia mensurável para p1. Provavelmente bash lendo e criando a variável da cauda.

Finalmente, o Total p1 executa ~ 150k chamadas do sistema vs. p2 740k (4,93 vezes maior).

Eliminando waitpid, p1 gasta 0,014416 segundos executando chamadas do sistema, p2 0,439132 segundos (30 vezes mais).

Portanto, parece que p2 passa a maior parte do tempo no espaço do usuário sem fazer nada exceto esperar que as chamadas do sistema sejam completadas e o kernel reorganize a memória, p1 executa mais gravações, mas é mais eficiente e causa significativamente menos carga do sistema portanto, mais rápido.

Conclusão

Eu nunca tentaria me preocupar com a codificação através da memória ao escrever um script bash, isso não significa dizer que você não tenta ser eficiente.

tail foi projetado para fazer o que faz, provavelmente memory maps do arquivo, para que seja eficiente para ler e permitir que o kernel otimize a E / S.

Uma maneira melhor de otimizar seu problema pode ser primeiro grep para '"sucesso":' linhas e depois contar os trues e os falsos, grep tem uma opção de contagem que evita novamente o wc -l ou mesmo melhor ainda, canalizar a cauda até awk e contar trues e falsifica concorrentemente. p2 não só demora muito, mas adiciona carga ao sistema enquanto a memória está sendo embaralhada com brics.

    

Answer 3

Na verdade, a primeira solução lê o arquivo na memória também! Isso é chamado de cache e é feito automaticamente pelo sistema operacional.

E como já explicado corretamente por mikeserv a primeira solução exclui grep enquanto o arquivo está sendo lido enquanto a segunda solução o executa após o arquivo foi lido por tail .

Portanto, a primeira solução é mais rápida devido a várias otimizações. Mas isso nem sempre tem que ser verdade. Para arquivos realmente grandes que o SO decide não armazenar em cache, a segunda solução pode se tornar mais rápida. Mas note que, para arquivos ainda maiores que não caberão na sua memória, a segunda solução não funcionará.

    

Answer 4

Eu acho que a principal diferença é simplesmente que echo é lento. Considere isto:

$ time (tail -n 1000000 foo | grep 'true' | wc -l; 
        tail -n 1000000 foo | grep 'false' | wc -l;)
666666
333333

real    0m0.999s
user    0m1.056s
sys     0m0.136s

$ time (log=$(tail -n 1000000 foo); echo "$log" | grep 'true' | wc -l; 
                                    echo "$log" | grep 'false' | wc -l)
666666
333333

real    0m4.132s
user    0m3.876s
sys     0m0.468s

$ time (tail -n 1000000 foo > bb;  grep 'true' bb | wc -l; 
                                   grep 'false' bb | wc -l)
666666
333333

real    0m0.568s
user    0m0.512s
sys     0m0.092s

Como você pode ver acima, a etapa demorada é imprimir os dados. Se você simplesmente redireciona para um novo arquivo e verifica que é muito mais rápido ao ler o arquivo apenas uma vez.

E, conforme solicitado, com uma string aqui:

 $ time (log=$(tail -n 1000000 foo); grep 'true' <<< $log | wc -l; 
                                     grep 'false' <<< $log | wc -l  )
1
1

real    0m7.574s
user    0m7.092s
sys     0m0.516s

Este é ainda mais lento, presumivelmente porque a string here está concatenando todos os dados em uma linha longa e isso irá desacelerar o grep :

$ tail -n 1000000 foo | (time grep -c 'true')
666666

real    0m0.500s
user    0m0.472s
sys     0m0.000s

$ tail -n 1000000 foo | perl -pe 's/\n/ /' | (time grep -c 'true')
1

real    0m1.053s
user    0m0.048s
sys     0m0.068s

Se a variável for citada de forma que nenhuma divisão ocorra, as coisas serão um pouco mais rápidas:

 $ time (log=$(tail -n 1000000 foo); grep 'true' <<< "$log" | wc -l; 
                                     grep 'false' <<< "$log" | wc -l  )
666666
333333

real    0m6.545s
user    0m6.060s
sys     0m0.548s

Mas ainda é lento porque a etapa de limitação de taxa é a impressão dos dados.

    

Answer 5

Eu também experimentei isso ... Primeiro, criei o arquivo:

printf '"success": "true"
        "success": "true"
        "success": "false"
        %.0b' 'seq 1 500000' >|/tmp/log

Se você mesmo executar o que precede, deverá criar 1,5 milhões de linhas em /tmp/log com proporção de 2: 1 de "success": "true" linhas para "success": "false" linhas.

A próxima coisa que fiz foi executar alguns testes. Executei todos os testes por meio de um proxy sh , então time só precisaria assistir a um único processo - e, portanto, poderia mostrar um único resultado para o trabalho inteiro .

Este parece ser o mais rápido, apesar de adicionar um segundo descritor de arquivo e tee, embora eu possa explicar por quê:

    time sh <<-\CMD
        . <<HD /dev/stdin | grep '"success": "true"' | wc -l
            tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
                grep '"success": "false"' |\
                    wc -l 1>&2 & } 3>&1 &
        HD
    CMD
666666
333334
sh <<<''  0.11s user 0.08s system 84% cpu 0.224 total

Este é o seu primeiro:

    time sh <<\CMD
        tail -n 1000000 /tmp/log | grep '"success": "true"' | wc -l
        tail -n 1000000 /tmp/log | grep '"success": "false"' | wc -l
    CMD

666666
333334
sh <<<''  0.31s user 0.17s system 148% cpu 0.323 total

E o seu segundo:

    time sh <<\CMD
        log=$(tail -n 1000000 /tmp/log)
        echo "$log" | grep '"success": "true"' | wc -l
        echo "$log" | grep '"success": "false"' | wc -l
    CMD
666666
333334
sh <<<''  2.12s user 0.46s system 108% cpu 2.381 total

Você pode ver que nos meus testes houve mais de 3 * de diferença na velocidade ao lê-lo em uma variável como você fez.

Eu acho que parte disso é que uma variável shell precisa ser dividida e manipulada pelo shell quando está sendo lida - não é um arquivo.

Um here-document por outro lado, para todos os efeitos, é file - a file descriptor, . E como todos sabemos - o Unix funciona com arquivos .

O que é mais interessante para mim sobre here-docs é que você pode manipular o file-descriptors - como uma sequência |pipe - e executá-los. Isso é muito útil, pois permite que você tenha um pouco mais de liberdade ao apontar seu |pipe para onde quiser.

Eu tive que tee o tail porque o primeiro grep come o here-doc |pipe e não há mais nada para o segundo ler. Mas desde que eu |piped em /dev/fd/3 e o peguei novamente para passar para >&1 stdout, , não importava muito. Se você usar grep -c , como muitos outros recomendam:

    time sh <<-\CMD
        . <<HD /dev/stdin | grep -c '"success": "true"'
            tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
                grep -c '"success": "false"' 1>&2 & } 3>&1 &
        HD
    CMD
666666
333334
sh <<<''  0.07s user 0.04s system 62% cpu 0.175 total

É ainda mais rápido.

Mas quando eu o executo sem . sourcing , o heredoc não é capaz de fazer o primeiro processo com sucesso para executá-los totalmente simultaneamente. Aqui está sem totalmente fundo:

    time sh <<\CMD
        tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
            grep -c '"success": "true"' 1>&2 & } 3>&1 |\
                grep -c '"success": "false"'
    CMD
666666
333334
sh <<<''  0.10s user 0.08s system 109% cpu 0.165 total

Mas quando eu adiciono o &:

    time sh <<\CMD
        tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
            grep -c '"success": "true"' 1>&2 & } 3>&1 & |\
                grep -c '"success": "false"'
    CMD
sh: line 2: syntax error near unexpected token '|'

Ainda assim, a diferença parece ser de apenas alguns centésimos de segundo, pelo menos para mim, então aceite como quiser.

De qualquer forma, o motivo pelo qual ele é executado mais rapidamente com tee é porque ambos greps são executados ao mesmo tempo com apenas uma invocação de tail. tee duplica o arquivo para nós e o divide para o segundo grep processo todos in-stream - tudo é executado de uma vez do começo ao fim, então todos terminam na mesma hora , também.

Voltando ao seu primeiro exemplo:

    tail | grep | wc #wait til finished
    tail | grep | wc #now we're done

E o seu segundo:

    var=$( tail ) ; #wait til finished
    echo | grep | wc #wait til finished
    echo | grep | wc #now we're done

Mas quando dividimos nossa entrada e executamos nossos processos simultaneamente:

          3>&1  | grep #now we're done
              /        
    tail | tee  #both process together
              \  
          >&1   | grep #now we're done