How can I time a pipe?
It is working.
The different parts of a pipeline are executed concurrently. The only thing that synchronises/serialises the processes in the pipeline is IO, i.e. one process writing to the next process in the pipeline and the next process reading what the first one writes. Apart from that, they are executing independently of each other.
Since there is no reading or writing happening between the processes in your pipeline, the time take to execute the pipeline is that of the longest sleep
call.
You might as well have written
time ( foo.sh & bar.sh &; wait )
Terdon posted a couple of slightly modified example scripts in the chat:
#!/bin/sh
# This is "foo.sh"
echo 1; sleep 1
echo 2; sleep 1
echo 3; sleep 1
echo 4
and
#!/bin/sh
# This is "bar.sh"
sleep 2
while read line; do
echo "LL $line"
done
sleep 1
The query was "why does time ( sh foo.sh | sh bar.sh )
return 4 seconds rather than 3+3 = 6 seconds?"
To see what's happening, including the approximate time each command is executed, one may do this (the output contains my annotations):
$ 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
So, to conclude, the pipeline takes 4 seconds, not 6, due to the buffering of the output of the first two calls to echo
in foo.sh
.
Would this be a better example?
$ 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
The scripts busyloop for 3 and 4 seconds (resp.), taking a total of 4 seconds in real time because of parallel execution, and 7 seconds of CPU time. (at least approximately.)
Or this:
$ time ( sleep 2; echo) | ( read x; sleep 3 )
real 0m5.004s
user 0m0.000s
sys 0m0.000s
These don't run in parallel, so the total time taken is 5 seconds. It's all spent sleeping, so no CPU time used.
If you have sysdig
you can insert tracers at arbitrary points, assuming you can modify the code to add the necessary writes to /dev/null
echo '>::blah::' >/dev/null
foo.sh | bar.sh
echo '<::blah::' >/dev/null
(but that fails your "single operation" requirement) and then record things via
$ sudo sysdig -w blalog "span.tags contains blah"
and then you'll probably need a sysdig chisel to export just the durations
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
which once saved to your sysdig/chisels
directory as the file
spantagduration.lua
can be used as
$ sysdig -r blalog -c spantagduration
...
Or you can play around with csysdig
or the JSON output.