Como posso tempo um tubo?

Question

Eu quero time um comando que consiste em dois comandos separados com uma saída de tubulação para outra. Por exemplo, considere os dois scripts abaixo:

$ cat foo.sh
#!/bin/sh
sleep 4

$ cat bar.sh
#!/bin/sh
sleep 2

Agora, como posso obter time para relatar o tempo gasto por foo.sh | bar.sh (e sim, eu sei que o pipe não faz sentido aqui, mas isso é apenas um exemplo)? Ele funciona como esperado se eu executá-los sequencialmente em um subshell sem canalizar:

$ time ( foo.sh; bar.sh )

real    0m6.020s
user    0m0.010s
sys     0m0.003s

Mas não consigo que funcione quando estiver trabalhando:

$ time ( foo.sh | bar.sh )

real    0m4.009s
user    0m0.007s
sys     0m0.003s

$ time ( { foo.sh | bar.sh; } )

real    0m4.008s
user    0m0.007s
sys     0m0.000s

$ time sh -c "foo.sh | bar.sh "

real    0m4.006s
user    0m0.000s
sys     0m0.000s

Li uma questão semelhante ( Como executar o tempo em vários comandos E escrever a saída de tempo para o arquivo? ) e também tentou o executável time autônomo:

$ /usr/bin/time -p sh -c "foo.sh | bar.sh"
real 4.01
user 0.00
sys 0.00

Não funciona mesmo se eu criar um terceiro script que apenas execute o canal:

$ cat baz.sh
#!/bin/sh
foo.sh | bar.sh

E, em seguida, tempo que:

$ time baz.sh

real    0m4.009s
user    0m0.003s
sys     0m0.000s

Curiosamente, não parece que time sai assim que o primeiro comando é feito. Se eu alterar bar.sh para:

#!/bin/sh
sleep 2
seq 1 5

E, em seguida, time novamente, eu esperava que a saída time fosse impressa antes do seq , mas não é:

$ time ( { foo.sh | bar.sh; } )
1
2
3
4
5

real    0m4.005s
user    0m0.003s
sys     0m0.000s

Parece que time não conta o tempo gasto para executar bar.sh , apesar de esperar que ele termine antes de imprimir seu relatório ¹ .

Todos os testes foram executados em um sistema Arch e usando bash 4.4.12 (1) -release. Eu só posso usar o bash para o projeto do qual faz parte, mesmo que zsh ou algum outro shell poderoso possa contorná-lo, isso não será uma solução viável para mim.

Então, como posso obter o tempo que um conjunto de comandos canalizados levou para ser executado? E enquanto estamos nisso, por que isso não funciona? Parece que time sai imediatamente assim que o primeiro comando é concluído. Por quê?

Eu sei que posso obter os momentos individuais com algo assim:

( time foo.sh ) 2>foo.time | ( time bar.sh ) 2> bar.time

Mas eu ainda gostaria de saber se é possível cronometrar a coisa toda como uma única operação.

¹ _{Isso não parece ser um problema de buffer, tentei executar os scripts com unbuffered e stdbuf -i0 -o0 -e0 e os números ainda foram impressos antes da saída time .}

    

Answer 1

está funcionando.

As diferentes partes de um pipeline são executadas simultaneamente. A única coisa que sincroniza / serializa os processos no pipeline é IO, ou seja, um processo sendo gravado no próximo processo no pipeline e o próximo processo lendo o que o primeiro escreve. Além disso, eles estão executando independentemente um do outro.

Como não há leitura ou gravação acontecendo entre os processos em seu pipeline, o tempo gasto para executar o pipeline é o da chamada sleep mais longa.

Você pode muito bem ter escrito

time ( foo.sh & bar.sh &; wait )

Terdon postou alguns exemplos de scripts levemente modificados no bate-papo :

#!/bin/sh
# This is "foo.sh"
echo 1; sleep 1
echo 2; sleep 1
echo 3; sleep 1
echo 4

e

#!/bin/sh
# This is "bar.sh"
sleep 2
while read line; do
  echo "LL $line"
done
sleep 1

A consulta foi "por que time ( sh foo.sh | sh bar.sh ) retorna 4 segundos em vez de 3 + 3 = 6 segundos?"

Para ver o que está acontecendo, incluindo o tempo aproximado que cada comando é executado, pode-se fazer isso (a saída contém minhas anotações):

$ time ( env PS4='$SECONDS foo: ' sh -x foo.sh | PS4='$SECONDS bar: ' sh -x bar.sh )
0 bar: sleep 2
0 foo: echo 1     ; The output is buffered
0 foo: sleep 1
1 foo: echo 2     ; The output is buffered
1 foo: sleep 1
2 bar: read line  ; "bar" wakes up and reads the two first echoes
2 bar: echo LL 1
LL 1
2 bar: read line
2 bar: echo LL 2
LL 2
2 bar: read line  ; "bar" waits for more
2 foo: echo 3     ; "foo" wakes up from its second sleep
2 bar: echo LL 3
LL 3
2 bar: read line
2 foo: sleep 1
3 foo: echo 4     ; "foo" does the last echo and exits
3 bar: echo LL 4
LL 4
3 bar: read line  ; "bar" fails to read more
3 bar: sleep 1    ; ... and goes to sleep for one second

real    0m4.14s
user    0m0.00s
sys     0m0.10s

Então, para concluir, o pipeline leva 4 segundos, não 6, devido ao buffer da saída das duas primeiras chamadas para echo em foo.sh .

    

Answer 2

Este seria um exemplo melhor?

$ time perl -e 'alarm(3); 1 while 1;' | perl -e 'alarm(4); 1 while 1;'
Alarm clock

real    0m4.004s
user    0m6.992s
sys     0m0.004s

Os scripts busyloop por 3 e 4 segundos (resp.), levando um total de 4 segundos em tempo real por causa da execução paralela e 7 segundos de tempo de CPU. (pelo menos aproximadamente.)

Ou isto:

$ time ( sleep 2; echo) | ( read x; sleep 3 )

real    0m5.004s
user    0m0.000s
sys     0m0.000s

Estes não funcionam em paralelo, pelo que o tempo total gasto é de 5 segundos. Está tudo gasto dormindo, então não há tempo de uso da CPU.

    

Answer 3

Se você tem sysdig você pode inserir marcadores em pontos arbitrários, supondo que você pode modificar o código para adicionar as gravações necessárias para /dev/null

echo '>::blah::' >/dev/null
foo.sh | bar.sh
echo '<::blah::' >/dev/null

(mas isso falha no seu requisito de "operação única") e, em seguida, grava as coisas via

$ sudo sysdig -w blalog "span.tags contains blah"

e, em seguida, você provavelmente precisará de um cinzel sysdig para exportar apenas as durações

description = "Exports sysdig span tag durations";
short_description = "Export span tag durations.";
category = "Tracers";

args = {}

function on_init()
    ftags = chisel.request_field("span.tags")
    flatency = chisel.request_field("span.duration")
    chisel.set_filter("evt.type=tracer and evt.dir=<")
    return true
end

function on_event()
    local tags = evt.field(ftags)
    local latency = evt.field(flatency)
    if latency then
        print(tostring(tags) .. "\t" .. tonumber(latency) / 1e9)
    end
    return true
end

que, uma vez salvo no diretório sysdig/chisels , como o arquivo spantagduration.lua pode ser usado como

$ sysdig -r blalog -c spantagduration
...

Ou você pode brincar com csysdig ou a saída JSON.