Bug/limitation in 'time'

[Bruce Dawson]

Configuration Information [Automatically generated, do not change]:
Machine: i686
OS: linux-gnu
Compiler: gcc
Compilation CFLAGS:  -DPROGRAM='bash' -DCONF_HOSTTYPE='i686'
-DCONF_OSTYPE='linux-gnu' -DCONF_MACHTYPE='$
uname output: Linux Ubuntu1m 3.2.0-35-generic-pae #55-Ubuntu SMP Wed Dec 5
18:04:39 UTC 2012 i686 i686 i$
Machine Type: i686-pc-linux-gnu

Bash Version: 4.2
Patch Level: 24
Release Status: release

Description:
        The basic problem is that if you time an operation that starts lots
of sub processes - an operation whose execution is dominated by starting
short-lived subprocesses - then time does not accurately record CPU time. In
fact it is off by a lot. It reports the system as being about 75% idle when
the task is entirely CPU bound. I've verified that the task is CPU bound by
using iostat, mpstat, perf, and a few other programs.

My theory is that the process creation and teardown time is 'lost' and not
attributed to the parent or child process. Therefore this is probably a
limitation of the numbers made available by the kernel. And therefore it is
probably best addressed (in the short term anyway) by acknowledging this
limitation in the man page.

I think it's important because when I hit this problem (using $(expr) for
looping in shell scripts is slow) I initially assumed that my task was not
CPU bound, because that is what 'time' told me. This then led me down the
wrong path in my investigation.

I ran bashbug from a VM running Linux but I have reproed this bug on several
'normal' installs of Ubuntu, both 32-bit and 64-bit, on
six-core/twelve-thread machines.

Repeat-By:
       The great thing about this bug/weakness is that it is extremely easy
to reproduce. The shell script below does the trick.

#!/bin/bash
# Warning: this code is excessively slow
function ExprCount() {
                i=$1
                while [ $i -gt 0 ]; do
                                i=$(expr $i - 1)
                                #sleep 0.001
                done
                echo Just did $1 iterations using expr math
}
time ExprCount 1000

Here are sample results running it - note that I'm using both bash-time and
/usr/bin/time, and there results are quite similar, except for rounding
differences. 

$ /usr/bin/time counttest.sh
Just did 1000 iterations using expr math

real        0m0.737s
user       0m0.016s
sys          0m0.124s
0.01user 0.12system 0:00.74elapsed 19%CPU (0avgtext+0avgdata
5376maxresident)k
0inputs+0outputs (0major+322859minor)pagefaults 0swaps

In particular notice that the sum of user+sys time is significantly lower
than 'real' time, despite the fact that this test is 100% CPU bound.

Fix:
        The documentation for the 'time' built-in (and the 'time'
stand-alone command for that matter) should be updated to acknowledge that
the CPU time totals will be short, sometimes significantly.