How to debug bash script and get runtime for each command

Question

I have a bash script that takes about 5 seconds. I would like to debug it and determine which teams occupy the longest. What is the best way to do this? Is there a flag that I can set? Setting #!/bin/bash -vx really doesn't help. What I want is basically runtime by line number.

Answer 1

This is the closest possible answer with the bash built-in debugging function, as it gives general time information from the time the script was run.

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

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

Same thing, 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 may go to microsecond precision, just keep in mind that you are using bash :).

Exam 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 

Debug output example:

 +[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 part of the script by including it in 'set -x' when starting debugging and 'debug + x' at the end of debugging. The synchronization data will continue to be correctly counted from the moment it is launched.

Adding

For completeness, if you need differential synchronization data, you can redirect debugging information to a file and process it later.

In 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 when redirecting debugging to a file:

 ./example.sh 2>example.dbg 

And print the differential debug time with this (spans 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 

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 execution time of individual commands / functions.

For instance:

 [ 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 this script leads to 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 

Answer 3

You can use set -x to let the script print each command before executing it. I do not know how to automatically add commands. You can sprinkle date commands throughout the script to mark the time.

Answer 4

Try the following:

 sed 's/^\([^#]\)/time \1/' script.sh>tmp.sh && ./tmp.sh 

he adds a time command to all teams without commands