Alain Kelder is a Giant Dork

How to benchmark individual shell script sections to identify slow parts

I use a couple of different methods for this, depending on whether I'm writing a new script and want to benchmark different approaches or need to debug an existing script to identify slow sections.

When writing something new and trying to identify the most efficient method for accomplishing a task, I'll usually take a block of code and save as multiple separate functions, each using a different method, then benchmark each function to compare performance costs of different approaches using the Bash builtin "time".

For example:

OneWay()
{
  some code
  more code
}

OtherWay()
{
  some code
  more code
}

Then time each function:

for cmd in OneWay OtherWay; do
  echo -e "\n=== $cmd ==="
  for run in {1..3}; do
    time $cmd &> /dev/null
  done
done

=== OneWay ===

real	0m0.421s
user	0m0.416s
sys	0m0.004s

real	0m0.418s
user	0m0.408s
sys	0m0.008s

real	0m0.416s
user	0m0.412s
sys	0m0.000s

=== OtherWay ===

real	0m0.580s
user	0m0.572s
sys	0m0.004s

real	0m0.566s
user	0m0.564s
sys	0m0.004s

real	0m0.570s
user	0m0.564s
sys	0m0.004s

But if I want to benchmark individual sections of an existing script, something like the following might be better. First, insert the following function at the top of the script to be benchmarked:

RuntimePrint()
{
 duration=$(echo "scale=3;(${m2t}-${m1t})/(1*10^09)"|bc|sed 's/^\./0./')
 echo -e "DEBUG: lines ${m1l}-${m2l}\t${duration}\tsec"
}

Then wrap the parts of the script to be benchmarked as follows:

m1t=$(date +%s%N); m1l=$LINENO
# some code here
m2t=$(date +%s%N); m2l=$LINENO; RuntimePrint

m1t=$(date +%s%N); m1l=$LINENO
# more code here
m2t=$(date +%s%N); m2l=$LINENO; RuntimePrint

m1t=$(date +%s%N); m1l=$LINENO
# even more 
# code here
m2t=$(date +%s%N); m2l=$LINENO; RuntimePrint

Then run the script as usual or pipe output to grep to just get the benchmark results without script's usual output:

SomeScript.sh | grep "^DEBUG:" | column -t

DEBUG:  lines  9-18     0.004   sec
DEBUG:  lines  20-25    0.012   sec
DEBUG:  lines  27-32    0.008   sec
DEBUG:  lines  34-39    0.004   sec
DEBUG:  lines  41-46    0.004   sec
DEBUG:  lines  48-54    0       sec
DEBUG:  lines  56-63    0.008   sec
DEBUG:  lines  65-70    0.236   sec
DEBUG:  lines  72-90    78.647  sec
DEBUG:  lines  92-94    0.076   sec
DEBUG:  lines  96-111   0.024   sec
DEBUG:  lines  113-115  0.004   sec