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.
