RE: Bug/limitation in 'time'

[Bruce Dawson]

The man page is clear that it is displaying the results of wait3(). However
it doesn't mention that this means that sub-process startup time is not
accounted for. That's what I feel should be clarified. Otherwise a CPU bound
task may appear to not be CPU bound.

My expectation is that the sum of 'user' and 'sys' time should equal the
elapsed time because the overall task is 100% CPU bound (I've confirmed
this). It is unfortunate that the sub-process startup time is not accounted
for in 'user' or 'sys' time, and I think it would be appropriate to document
this.

Anyway, if the docs can be updated I think that would be great. If not, no
worries.

-----Original Message-----
From: Pierre Gaston [mailto:pierre.gaston@gmail.com] 
Sent: Saturday, March 16, 2013 11:31 PM
To: Bruce Dawson
Cc: bug-bash@gnu.org
Subject: Re: Bug/limitation in 'time'

On Sun, Mar 17, 2013 at 4:33 AM, Bruce Dawson
<brucedawson@cygnus-software.com> wrote:
> Thanks -- good to know that there is a fast and POSIX compliant method 
> of doing this. I should have included my optimized counting loop -- 
> it's what we switched to when we realized that $(expr) was a problem. Here
it is now:
>
> # This code performs quite well
> function BashCount() {
>         i=$1
>         while [ $i -gt 0 ]; do
>                 (( i-- ))
>         done
>         echo Just did $1 iterations using bash math } time BashCount 
> 150000
>
> It's a *lot* faster, of course. BTW, I've poked around in the 'time' 
> source code enough to know that it is just displaying the results of 
> wait3(), so the misleading CPU consumption information is ultimately a 
> wait3()/kernel issue. However showing this in the documentation would be
great.

At least the man page of time on my ubuntu system is pretty much clear about
what it does.

The result is not striking me as impossible though, I can imagine a lot of
real time spent waiting for the scheduler to run expr and then to run bash
again.

I tried a little experiment that I think shows the importance of the
scheduler on the real time result:
I run at the same time this little loop with different "niceness"
i=0;time while ((i++<10000));do /bin/echo -n;done

sudo nice -n 19 bash -c 'i=0;time while ((i++<10000));do /bin/echo -n;done'
2>&1| sed s/^/19:\ / & sudo nice -n -20 bash -c 'i=0;time while
((i++<10000));do /bin/echo -n;done' 2>&1| sed s/^/-20:\ /

I get:
-20: real       0m9.331s
-20: user       0m0.468s
-20: sys        0m1.504s

19: real        0m14.004s
19: user        0m0.532s
19: sys 0m1.660s

so the nicer loop takes twice as much real time indicating that much real
time is spent waiting for the process to run.