Debug execution time of bash script

bash_debug_time.sh

# Solutions from https://stackoverflow.com/a/20855353




# SOLUTION 1 : analyse at the current level of execution (do not step into code)

# get https://www.f-hauri.ch/vrac/cours_truc-et-astuces_2012-04-03/add/elap.bash-v2

# Elap bash source file Version 2
# Based on /proc/timer_list only
# Useable functions
elap()          { elapGetNow;elapCalc;elapShow "$@";elapCnt;}
elapTotal()     { elapGetNow;elapCalc2;elapShowTotal "$@";}
elapBoth()      { elapGetNow;elapCalc;elapCalc2;elapShowBoth "$@";elapCnt;}
elapReset()     { elapGetNow;elapCnt;}
elapResetTotal(){ elapGetNow;elapCntTotal;}
elapResetBoth() { elapGetNow;elapCntBoth;}

# Semi internal functions
elapShow()      { echo -e "$_elap $@";}
elapShowTotal() { echo -e "$_elap2 $@";}
elapShowBoth()  { echo -e "$_elap $_elap2 $@";}

# Internal functions
elapCnt()       { _eLast=$_eNow ;}
elapCntTotal()  { _eLast2=$_eNow;}
elapCntBoth()   { _eLast=$_eNow ; _eLast2=$_eNow;}
elapGetNow()    {
    read -dk -a_eNow </proc/timer_list;
    _eNow=${_eNow[8]}
}
elapCalc() { 
    _elap=000000000$((_eNow - _eLast))
    printf -v _elap "%16.9f" \
	"${_elap:0:${#_elap}-9}"."${_elap:${#_elap}-9}"
}
elapCalc2() { 
    _elap2=000000000$((_eNow - _eLast2))
    printf -v _elap2 "%16.9f" \
	"${_elap2:0:${#_elap2}-9}"."${_elap2:${#_elap2}-9}"
}

export _eNow _eLast _eLast2 _elap _elap2

[ "$1" == "trap2" ] || [ "$1" == "trap" ] || [ "$1" == "init" ] && elapResetBoth
if [ "$1" == "trap" ] ;then
    if [ "${-/*i*/1}" == "1" ] ;then
	trap '[ "${BASH_COMMAND%elap*}" == "$BASH_COMMAND" ] && {
	     elapReset;BASH_LAST=$BASH_COMMAND; }' debug
	PROMPT_COMMAND='elap $BASH_LAST'
    else
	export BASH_LAST=Starting
	trap 'trap -- debug;elapTotal EXIT;exit 0' 0
	trap 'elap $BASH_LAST;BASH_LAST=$BASH_COMMAND' debug
    fi
else
    if [ "$1" == "trap2" ] ;then
	if [ "${-/*i*/1}" == "1" ] ;then
	    trap '[ "${BASH_COMMAND%elap*}" == "$BASH_COMMAND" ] && {
		 elapReset;BASH_LAST=$BASH_COMMAND; }' debug
	    PROMPT_COMMAND='elapBoth $BASH_LAST'
	else
	    export BASH_LAST=Starting
	    trap 'trap -- debug;elapBoth EXIT;exit 0' 0
	    trap 'elapBoth $BASH_LAST;BASH_LAST=$BASH_COMMAND' debug
	fi
    fi
fi




# Use of elap-bash :
# at the beginning of the script do
# one column execution time
. elap.bash-v2 trap
# OR
# two columns execution time with diff time for each line
. elap.bash-v2 trap2

# inside a function to analyse this function
foo() {
	. elap.bash-v2 trap2
	echo "bar"
}









# SOLUTION 2 : analyse detail with step into each sourced files
#               might have problem when script to analyse play with redirection too

# declare this bloc at the beginning of the script to test

exec 3>&2 2> >( tee /tmp/sample.log |
                  sed -u 's/^.*$/now/' |
                  date -f - +%s.%N >/tmp/sample.time)

# declare this to start debugging at this line
set -x

# declare this to stop debugging at this line
set +x
exec 2>&3 3>&-




# to analise output, launch this

 paste <(
     while read tim ;do
         [ -z "$last" ] && last=${tim//.} && first=${tim//.}
         crt=000000000$((${tim//.}-10#0$last))
         ctot=000000000$((${tim//.}-10#0$first))
         printf "%12.9f %12.9f\n" ${crt:0:${#crt}-9}.${crt:${#crt}-9} \
                                  ${ctot:0:${#ctot}-9}.${ctot:${#ctot}-9}
         last=${tim//.}
       done < /tmp/sample.time
   ) /tmp/sample.log