Come eseguire il debug di uno script di bash e ottenere il tempo di esecuzione per comando

Question

Ho uno script bash che richiede circa 5 secondi per essere eseguito. Mi piacerebbe eseguirne il debug e determinare quali comandi impiegano più tempo. Qual è il modo migliore per fare questo? C'è una bandiera che posso impostare? L'impostazione #!/bin/bash -vx non è di grande aiuto. Quello che voglio è fondamentalmente il tempo di esecuzione per numero di riga.

Answer 1

È possibile utilizzare set -x affinché lo script stampi ogni comando prima che venga eseguito. Non conosco un modo per ottenere automaticamente i tempi di comando aggiunti. È possibile cospargere i comandi date in tutto lo script per contrassegnare l'ora.

Answer 2

È possibile utilizzare l'utilità time per misurare il tempo di esecuzione dei singoli comandi/funzioni.

Ad esempio:

[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 

esecuzione che i risultati dello script in qualcosa di simile al seguente:

[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

Prova questo:

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

si antepone un comando di tempo per tutti i non righe di comando

Answer 4

Questo è il più vicino possibile risposta con built-in funzione di debug di bash in quanto fornisce informazioni di tempistica complessiva dal momento di inizio dell'esecuzione dello script.

Nella parte superiore dello script aggiungere questo per un secondo conteggio:

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

stesso ma con millisecondi invece:

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

L'ultimo esempio può andare alla precisione microsecondo, basta tenere a mente stai usando 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 

Esempio output di debug:

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

Tenete a mente che è possibile eseguire il debug in modo selettivo una parte specifica dello script racchiudendolo in 'set -x' alla debug start e 'debug + x' alla fine del debug. I dati di temporizzazione verranno comunque visualizzati correttamente contati dall'inizio dell'esecuzione.

Addendum

Per completezza, se avete bisogno dei dati di temporizzazione differenziale è possibile reindirizzare le informazioni di debug in un file e di processo in seguito.

Dato questo script di esempio:

#!/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 durante il reindirizzamento di debug in un file:

./example.sh 2>example.dbg 

E l'uscita del differenziale di temporizzazione di debug con questo (si estende su più linee):

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 

Uscita:

+[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