¿Cómo puedo cronometrar una tubería?

Quiero timeun comando que consta de dos comandos separados con una salida de tubería a otra. Por ejemplo, considere los dos scripts a continuación:

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

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

Ahora, ¿cómo puedo timeinformar el tiempo que lleva foo.sh | bar.sh(y sí, sé que la tubería no tiene sentido aquí, pero esto es solo un ejemplo)? Funciona como se esperaba si los ejecuto secuencialmente en una subshell sin tuberías:

$ time ( foo.sh; bar.sh )

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

Pero no puedo hacer que funcione cuando canalizo:

$ 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

He leído una pregunta similar ( ¿Cómo ejecutar el tiempo en múltiples comandos Y escribir la salida de tiempo en el archivo? ) Y también probé el timeejecutable independiente :

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

Ni siquiera funciona si creo un tercer script que solo ejecuta la tubería:

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

Y luego cronometra que:

$ time baz.sh

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

Curiosamente, no parece que timesalga tan pronto como se complete el primer comando. Si cambio bar.sha:

#!/bin/sh
sleep 2
seq 1 5

Y, de timenuevo, esperaba que la timesalida se imprimiera antes seqpero no lo es:

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

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

Parece timeque no cuenta el tiempo que tardó en ejecutarse a bar.shpesar de esperar a que termine antes de imprimir su informe ¹ .

Todas las pruebas se ejecutaron en un sistema Arch y utilizando bash 4.4.12 (1) -release. Solo puedo usar bash para el proyecto del que forma parte, por lo que incluso si zshalgún otro poderoso shell puede evitarlo, esa no será una solución viable para mí.

Entonces, ¿cómo puedo obtener el tiempo que tardó en ejecutarse un conjunto de comandos canalizados? Y, mientras estamos en eso, ¿por qué no funciona? Parece que timesale inmediatamente tan pronto como el primer comando ha terminado. ¿Por qué?

Sé que puedo obtener los tiempos individuales con algo como esto:

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

Pero aún me gustaría saber si es posible cronometrar todo como una sola operación.

¹ _{Esto no parece ser un problema de memoria intermedia, he intentado ejecutar los scripts con unbufferedy stdbuf -i0 -o0 -e0y el número todavía se imprimieron antes de la timesalida.}

Se está trabajando.

Las diferentes partes de una tubería se ejecutan simultáneamente. Lo único que sincroniza / serializa los procesos en la tubería es IO, es decir, un proceso que escribe en el siguiente proceso en la tubería y el siguiente proceso lee lo que escribe el primero. Aparte de eso, se ejecutan independientemente uno del otro.

Como no hay lectura ni escritura entre los procesos en su canalización, el tiempo que lleva ejecutar la canalización es el de la sleepllamada más larga .

También podrías haber escrito

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

Terdon publicó un par de scripts de ejemplo ligeramente modificados en el chat :

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

y

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

La consulta fue "¿por qué time ( sh foo.sh | sh bar.sh )devuelve 4 segundos en lugar de 3 + 3 = 6 segundos?"

Para ver qué sucede, incluido el tiempo aproximado que se ejecuta cada comando, uno puede hacer esto (la salida contiene mis anotaciones):

$ 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

Por lo tanto, para concluir, la tubería es de 4 segundos, no 6, debido al amortiguamiento de la salida de las dos primeras llamadas a echoen foo.sh.

¿Sería este un mejor ejemplo?

$ 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

Las secuencias de comandos ocupan el bucle durante 3 y 4 segundos (resp.), Tomando un total de 4 segundos en tiempo real debido a la ejecución paralela y 7 segundos de tiempo de CPU. (al menos aproximadamente)

O esto:

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

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

Estos no se ejecutan en paralelo, por lo que el tiempo total es de 5 segundos. Todo se pasa durmiendo, por lo que no se usa tiempo de CPU.

Si lo tiene sysdig, puede insertar trazadores en puntos arbitrarios, suponiendo que puede modificar el código para agregar las escrituras necesarias en/dev/null

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

(pero eso no cumple con el requisito de "operación única") y luego graba cosas a través de

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

y probablemente necesitarás un cincel sysdig para exportar solo las duraciones

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 una vez guardado en su sysdig/chiselsdirectorio como el archivo spantagduration.luapuede usarse como

$ sysdig -r blalog -c spantagduration
...

O puede jugar con csysdigo la salida JSON.