Conversation started May 10, 2017 at 13:06.
terdon
terdon
May 10, 2017 13:06
Does anyone know how to time a pipe?
Apparently, time seems to only report the time taken by the first command in the pipe, despite waiting for the whole thing to exit before printing its output.
Stephen Kitt
Stephen Kitt 
time ls | wc
on my system reports the time for ls and for wc
(on zsh)
I thought that was one of the reasons time is a shell built-in
so that it can time pipelines
Jeff Schaller
Jeff Schaller
@terdon I get the same behavior, despite the manpage saying it supports timelines (bash)
terdon
terdon
@StephenKitt apparently not
Stephen Kitt
Stephen Kitt
@terdon yeah I just saw your question there
I get the same thing on bash, no detail
so perhaps “use zsh”? ;-)
terdon
terdon
> All tests were run on an Arch system and using bash 4.4.12(1)-release. I can only use bash for the project this is a part of so even if zsh or some other powerful shell can get around it, that won't be a viable solution for me.
And yes, I can confirm zsh does this on Arch too.
Also, what gives? I find it very strange that time ( foo.sh | bar.sh ) doesn't work. It should be timing the subshell. And why does that fail when time (foo.sh; bar.sh) works?
Kusalananda
Kusalananda
May 10, 2017 13:17
Ah, you're talking about it here... didn't spot that.
@terdon What was the script with seq that you tried?
terdon
terdon
Gimme a few minutes, I need to drive someone.
Kusalananda
Kusalananda
@terdon No worries.
terdon
terdon
May 10, 2017 13:34
@Kusalananda here, for example: 
$ cat ~/scripts/foo.sh
#!/bin/sh
echo 1
sleep 1
echo 2
sleep 1
echo 3
sleep 1
echo 4
and: 
$ cat ~/scripts/bar.sh
#!/bin/sh
sleep 2
while read line; do
		echo "LL $line"
done
sleep 1
So, I would expect that to take 3 + 3 seconds, but: 
$ time ( foo.sh | bar.sh )
LL 1
LL 2
LL 3
LL 4

real	0m4.010s
user	0m0.003s
sys	0m0.003s
Kusalananda
Kusalananda
No, the first echo won't finish until bar has slept for 2 seconds.
Then each echo follow, once every second.
And then bar sleeps for two seconds.
I will test it and tthink
terdon
terdon
This might be more informative: 
$ time ( unbuffered foo.sh | unbuffered bar.sh )
1
2
LL 1
LL 2
LL 1
LL 2
3
LL 3
LL 3
4
LL 4
LL 4

real	0m4.016s
user	0m0.003s
sys	0m0.003s
It still doesn't report real time correctly though.
Stephen Kitt
Stephen Kitt
It does, because the pipes don't block per line
both scripts start simultaneously
bar sleeps
foo echoes 1
foo echoes 2
foo sleeps
bar reads 1 and 2
foo echoes 3, bar reads 3
foo sleeps
foo echoes 4, bar reads 4 and sleeps
foo finishes after echoing 4, after 3 secs
boo finishes after 4 secs
the total wall-clock time is 4 secs
terdon
terdon
I see. Yes. And I did time it externally and, as you say, it takes 4 seconds, not 6.
Because that's how pipes work terdon, you idiot.
And indeed, this does work as expected:
foo.sh: 
#!/bin/sh
sleep 3
echo foo
bar.sh: 
#!/bin/sh
while read line; do
		echo "LL $line"
done
sleep 5
$ time ( foo.sh | bar.sh )
LL foo

real 0m8.011s
user 0m0.007s
sys 0m0.003s
Stephen Kitt
Stephen Kitt
yes
there's also the fact that foo exits which stops bar's read loop
terdon
terdon
May 10, 2017 13:45
Yes, it makes sense now. Should have figured it out myself, really. Thanks @Kusalananda and @StephenKitt.
Stephen Kitt
Stephen Kitt
you're welcome!
running it with zsh foo.sh | bar.sh helps since it shows the separate execution times
 
Conversation ended May 10, 2017 at 13:45.