How to debug a bash script and get execution time per command

Question

I have a bash script which takes nearly 5 seconds to run. I'd like to debug it, and determine which commands are taking the longest. What is the best way of doing this? Is there a flag I can set? Setting #!/bin/bash -vx does not really help. What I want is basically execution time by line number.

Answer 1

This is as close as possible answer with built-in bash debug facility since it gives overall timing info from the script execution start time.

At the top of the script add this for a second count:

export PS4='+[${SECONDS}s][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;

Same but with milliseconds instead:

N=`date +%s%N`; export PS4='+[$(((`date +%s%N`-$N)/1000000))ms][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;

The last example can go to microsecond precision, just keep in mind you are using bash :).

Exampe script:

#!/bin/bash
N=`date +%s%N`
export PS4='+[$(((`date +%s%N`-$N)/1000000))ms][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;
sleep 1
exit

Example debug output:

+[3ms][/root/db_test.sh:5]: sleep 1
+[1012ms][/usr/local/bin/graphite_as_rand_stat.sh:6]: exit

Keep in mind that you can selectively debug a specific portion of the script by enclosing it in 'set -x' at the debug start and 'debug +x' at the debug end. The timing data will still show correctly counted from execution start.

Addendum

For sake of completeness, if you do need the differential timing data you can redirect the debug info to a file and process it afterwards.

Given this example script:

#!/bin/bash
N=`date +%s%N`
export PS4='+[$(((`date +%s%N`-$N)/1000000))ms][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;
sleep 1
for ((i=0;i<2;i++)); do
        o=$(($RANDOM*$RANDOM/$RANDOM))
        echo $o
        sleep 0.$o
done
exit

Run it while redirecting debug to a file:

./example.sh 2>example.dbg

And output the differential debug timing with this (covers multi-line):

p=0; cat example.dbg | while read l; do [[ ! ${l%%[*} =~ ^\+ ]] && echo $l && continue; i=`echo $l | sed 's#[^0-9]*\([0-9]\+\).*#\1#'`; echo $l | sed "s#${i}ms#${i}ms+$(($i-$p))ms#"; p=$i; done

The output:

+[2ms+2ms][./example.sh:5]: sleep 1
+[1006ms+1004ms][./example.sh:6]: (( i=0 ))
+[1009ms+3ms][./example.sh:6]: (( i<2 ))
+[1011ms+2ms][./example.sh:7]: o=19258
+[1014ms+3ms][./example.sh:8]: echo 19258
+[1016ms+2ms][./example.sh:9]: sleep 0.19258
+[1213ms+197ms][./example.sh:6]: (( i++ ))
+[1217ms+4ms][./example.sh:6]: (( i<2 ))
+[1220ms+3ms][./example.sh:7]: o=176
+[1226ms+6ms][./example.sh:8]: echo 176
+[1229ms+3ms][./example.sh:9]: sleep 0.176
+[1442ms+213ms][./example.sh:6]: (( i++ ))
+[1460ms+18ms][./example.sh:6]: (( i<2 ))
+[1502ms+42ms][./example.sh:11]: exit

Answer 2

You can use the time utility to measure the run time of your individual commands/functions.

For example:

[ben@imac ~]$ cat times.sh
#!/bin/bash

test_func ()
{
    sleep 1
    echo "test"
}

echo "Running test_func()"
time test_func
echo "Running a 5 second external command"
time sleep 5

Running that script results in something like the following:

[ben@imac ~]$ ./times.sh
Running test_func()
test

real    0m1.003s
user    0m0.001s
sys     0m0.001s
Running a 5 second external command

real    0m5.002s
user    0m0.001s
sys     0m0.001s