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.
4 Answers
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
4 Comments
mklement0
Very nicely done. The question is tagged
linux, but since the techniques are potentially useful on all platforms that support bash, let me add: sadly, %N doesn't work with date on BSD/OSX, so the milliseconds variant doesn't work there.mklement0
The milliseconds variant also does that, but to also get the
$SECONDS variant to start measuring from the point where set -x is run, execute SECONDS=0 first. Finally, it's worth mentioning that the act of measuring itself will increase execution time slightly, less so with the $SECONDS approach.
Joao Costa
Very nice answer. See also stackoverflow.com/questions/5014823/…
telotortium
@mklement0 to make it work on BSD/macOS, you can use the GNU variants of the tools
date and sed, which you can install using Homebrew or Macports on macOS (and I presume Ports has them on BSD).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
2 Comments
anishsane
do not use
test as function name. It's a shell built-in. rename it to test_time or something...mklement0
A nitpick:
time is by default a shell keyword (while also existing as an external utility, /usr/bin/time). Only the shell keyword is capable of measuring arbitrary shell commands as a whole (compare the output from time ls | sleep 1 to /usr/bin/time ls | sleep 1).You can use set -x to have the script print each command before it's executed. I don't know of a way to get command timings added automatically. You can sprinkle date commands throughout the script to mark the time.
1 Comment
12431234123412341234123
You could combine this with ts from moreutils
Try this:
sed 's/^\([^#]\)/time \1/' script.sh>tmp.sh && ./tmp.sh
it prepends a time command to all the non command lines
bash -x myscript.sh 2> >(ts -i)When you have moreutils installed and your script does not output to stderr. But the time duration given is of the previous command.