Mon shell bash prend environ 3-4 secondes à démarrer, alors que si je le lance avec --norc il s'exécute immédiatement.
J'ai commencé à "profiler" /etc/bash.bashrc et ~/.bashrc en insérant manuellement les instructions return et en cherchant des améliorations de la vitesse, mais ce n'est pas un processus quantitatif et il n'est pas efficace.
Comment profiler mes scripts bash et voir quelles commandes sont les plus longues à démarrer?
Si vous avez GNU date (ou une autre version de sortie nanosecondes), le faire au début de l' /etc/bash.bashrc (ou de l'endroit où vous souhaitez commencer une trace dans aucun script Bash):
PS4='+ $(date "+%s.%N")\011 '
exec 3>&2 2>/tmp/bashstart.$$.log
set -x
ajouter
set +x
exec 2>&3 3>&-
à la fin de l' ~/.bashrc (ou à la fin de la section de script Bash que vous souhaitez traçage à l'arrêt).
Vous devriez obtenir un journal de suivi en /tmp/bashstart.PID.log qui indique les secondes.nanosecondes horodatage de chaque commande a été exécutée. La différence d'un moment à l'autre est la quantité de temps que l'intervenant pas a pris.
Comme vous le cerner les choses, vous pouvez déplacer set -x plus tard et set +x plus tôt (ou support de plusieurs sections d'intérêt de manière sélective).
La lecture de ce et parce que le profilage est une étape importante, j'ai fait quelques test et de recherche au sujet de toute cette SORTE de question et déjà posté des réponses.
Il y a 3 réponse:
Enfin, un peu de comparaison des performances à la fin.
set -x et date mais avec peu de fourches
Prendre de @DennisWilliamson de l'idée, mais avec la syntaxe suivante, il y aura ony une première fourchette de 3 commandes:
exec 3>&2 2> >(tee /tmp/sample-time.$$.log |
sed -u 's/^.*$/now/' |
date -f - +%s.%N >/tmp/sample-time.$$.tim)
set -x
En faisant cela, vous exécutez date qu'une seule fois. Il y a une rapide démo/test pour montrer la façon dont il fonctionne:
for i in {1..4};do echo now;sleep .05;done| date -f - +%N
Exemple de script:
#!/bin/bash
exec 3>&2 2> >( tee /tmp/sample-$$.log |
sed -u 's/^.*$/now/' |
date -f - +%s.%N >/tmp/sample-$$.tim)
set -x
for ((i=3;i--;));do sleep .1;done
for ((i=2;i--;))
do
tar -cf /tmp/test.tar -C / bin
gzip /tmp/test.tar
rm /tmp/test.tar.gz
done
set +x
exec 2>&3 3>&-
En exécutant ce script, vous faites 2 fichiers: /tmp/sample-XXXX.log et /tmp/sample-XXXX.tim (où XXXX est l'id de processus de l'exécution d'un script).
Vous pourriez présenter à l'aide de paste:
paste tmp/sample-XXXX.{tim,log}
Ou vous pouvez même calculer diff temps:
paste <(
while read tim ;do
crt=000000000$((${tim//.}-10#0$last))
printf "%12.9f\n" ${crt:0:${#crt}-9}.${crt:${#crt}-9}
last=${tim//.}
done < sample-time.24804.tim
) sample-time.24804.log
1388487534.391309713 + (( i=3 ))
0.000080807 + (( i-- ))
0.000008312 + sleep .1
0.101304843 + (( 1 ))
0.000032616 + (( i-- ))
0.000007124 + sleep .1
0.101251684 + (( 1 ))
0.000033036 + (( i-- ))
0.000007054 + sleep .1
0.104013813 + (( 1 ))
0.000026959 + (( i-- ))
0.000006915 + (( i=2 ))
0.000006635 + (( i-- ))
0.000006844 + tar -cf /tmp/test.tar -C / bin
0.022655107 + gzip /tmp/test.tar
0.637042668 + rm /tmp/test.tar.gz
0.000823649 + (( 1 ))
0.000011314 + (( i-- ))
0.000006915 + tar -cf /tmp/test.tar -C / bin
0.016084482 + gzip /tmp/test.tar
0.627798263 + rm /tmp/test.tar.gz
0.001294946 + (( 1 ))
0.000023187 + (( i-- ))
0.000006845 + set +x
ou sur deux colonnes:
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 < sample-time.24804.tim
) sample-time.24804.log
Peut-rendu:
0.000000000 0.000000000 + (( i=3 ))
0.000080807 0.000080807 + (( i-- ))
0.000008312 0.000089119 + sleep .1
0.101304843 0.101393962 + (( 1 ))
0.000032616 0.101426578 + (( i-- ))
0.000007124 0.101433702 + sleep .1
0.101251684 0.202685386 + (( 1 ))
0.000033036 0.202718422 + (( i-- ))
0.000007054 0.202725476 + sleep .1
0.104013813 0.306739289 + (( 1 ))
0.000026959 0.306766248 + (( i-- ))
0.000006915 0.306773163 + (( i=2 ))
0.000006635 0.306779798 + (( i-- ))
0.000006844 0.306786642 + tar -cf /tmp/test.tar -C / bin
0.022655107 0.329441749 + gzip /tmp/test.tar
0.637042668 0.966484417 + rm /tmp/test.tar.gz
0.000823649 0.967308066 + (( 1 ))
0.000011314 0.967319380 + (( i-- ))
0.000006915 0.967326295 + tar -cf /tmp/test.tar -C / bin
0.016084482 0.983410777 + gzip /tmp/test.tar
0.627798263 1.611209040 + rm /tmp/test.tar.gz
0.001294946 1.612503986 + (( 1 ))
0.000023187 1.612527173 + (( i-- ))
0.000006845 1.612534018 + set +x
trap debug et /proc/timer_list sur les récentes GNU/Linux kernels, sans fourches.Sous GNU/Linux's les noyaux récents, vous pouvez trouver une /proc fichier nommé timer_list:
grep 'now at\|offset' /proc/timer_list
now at 5461935212966259 nsecs
.offset: 0 nsecs
.offset: 1383718821564493249 nsecs
.offset: 0 nsecs
Où l'heure actuelle est la somme des 5461935212966259 + 1383718821564493249, mais, en nanosecondes.
Donc, pour le calcul du temps écoulé, il n'est pas nécessaire de connaître le décalage.
Pour ce genre de travaux, je l'ai écrit elap.bash (V2), qui seront visés par la syntaxe suivante:
source elap.bash-v2
ou
. elap.bash-v2 init
(Voir les commentaires pour la syntaxe complète)
Donc, il vous suffit d'ajouter cette ligne en haut de votre script:
. elap.bash-v2 trap2
Petit échantillon:
#!/bin/bash
. elap.bash-v2 trap
for ((i=3;i--;));do sleep .1;done
elapCalc2
elapShowTotal \\e[1mfirst total\\e[0m
for ((i=2;i--;))
do
tar -cf /tmp/test.tar -C / bin
gzip /tmp/test.tar
rm /tmp/test.tar.gz
done
trap -- debug
elapTotal \\e[1mtotal time\\e[0m
Faire le rendu sur ma machine:
0.000947481 Starting
0.000796900 ((i=3))
0.000696956 ((i--))
0.101969242 sleep .1
0.000812478 ((1))
0.000755067 ((i--))
0.103693305 sleep .1
0.000730482 ((1))
0.000660360 ((i--))
0.103565001 sleep .1
0.000719516 ((1))
0.000671325 ((i--))
0.000754856 elapCalc2
0.316018113 first total
0.000754787 elapShowTotal \e[1mfirst total\e[0m
0.000711275 ((i=2))
0.000683408 ((i--))
0.075673816 tar -cf /tmp/test.tar -C / bin
0.596389329 gzip /tmp/test.tar
0.006565188 rm /tmp/test.tar.gz
0.000830217 ((1))
0.000759466 ((i--))
0.024783966 tar -cf /tmp/test.tar -C / bin
0.604119903 gzip /tmp/test.tar
0.005172940 rm /tmp/test.tar.gz
0.000952299 ((1))
0.000827421 ((i--))
1.635788924 total time
1.636657204 EXIT
À l'aide de trap2 au lieu de trap comme argument à la commande source:
#!/bin/bash
. elap.bash-v2 trap2
...
Rendra deux colonnes de la dernière commande et le total:
0.000894541 0.000894541 Starting
0.001306122 0.002200663 ((i=3))
0.001929397 0.004130060 ((i--))
0.103035812 0.107165872 sleep .1
0.000875613 0.108041485 ((1))
0.000813872 0.108855357 ((i--))
0.104954517 0.213809874 sleep .1
0.000900617 0.214710491 ((1))
0.000842159 0.215552650 ((i--))
0.104846890 0.320399540 sleep .1
0.000899082 0.321298622 ((1))
0.000811708 0.322110330 ((i--))
0.000879455 0.322989785 elapCalc2
0.322989785 first total
0.000906692 0.323896477 elapShowTotal \e[1mfirst total\e[0m
0.000820089 0.324716566 ((i=2))
0.000773782 0.325490348 ((i--))
0.024752613 0.350242961 tar -cf /tmp/test.tar -C / bin
0.596199363 0.946442324 gzip /tmp/test.tar
0.003007128 0.949449452 rm /tmp/test.tar.gz
0.000791452 0.950240904 ((1))
0.000779371 0.951020275 ((i--))
0.030519702 0.981539977 tar -cf /tmp/test.tar -C / bin
0.584155405 1.565695382 gzip /tmp/test.tar
0.003058674 1.568754056 rm /tmp/test.tar.gz
0.000955093 1.569709149 ((1))
0.000919964 1.570629113 ((i--))
1.571516599 total time
0.001723708 1.572352821 EXIT
strace
Oui, strace pourrait faire le travail:
strace -q -f -s 10 -ttt sample-script 2>sample-script-strace.log
Mais il peut faire beaucoup de choses!
wc sample-script-strace.log
6925 57637 586518 sample-script-strace.log
Utilisant de plus en plus restreint de commande:
strace -f -s 10 -ttt -eopen,access,read,write ./sample-script 2>sample-script-strace.log
D'un dumping de super briquet journal:
4519 36695 374453 sample-script-strace.log
Selon ce que vous recherchez, vous pouvez être plus restrictif:
strace -f -s 10 -ttt -eaccess,open ./sample-script 2>&1 | wc
189 1451 13682
La lecture sera un peu plus difficile:
{
read -a first
first=${first//.}
last=$first
while read tim line;do
crt=000000000$((${tim//.}-last))
ctot=000000000$((${tim//.}-first))
printf "%9.6f %9.6f %s\n" ${crt:0:${#crt}-6}.${crt:${#crt}-6} \
${ctot:0:${#ctot}-6}.${ctot:${#ctot}-6} "$line"
last=${tim//.}
done
} < <(
sed </tmp/sample-script.strace -e '
s/^ *//;
s/^\[[^]]*\] *//;
/^[0-9]\{4\}/!d
')
0.000110 0.000110 open("/lib/x86_64-linux-gnu/libtinfo.so.5", O_RDONLY) = 4
0.000132 0.000242 open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY) = 4
0.000121 0.000363 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY) = 4
0.000462 0.000825 open("/dev/tty", O_RDWR|O_NONBLOCK) = 4
0.000147 0.000972 open("/usr/lib/locale/locale-archive", O_RDONLY) = 4
...
0.000793 1.551331 open("/etc/ld.so.cache", O_RDONLY) = 4
0.000127 1.551458 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY) = 4
0.000545 1.552003 open("/usr/lib/locale/locale-archive", O_RDONLY) = 4
0.000439 1.552442 --- SIGCHLD (Child exited) @ 0 (0) ---
L'original script bash n'est pas si facile à suivre ce...
Pour faire des tests, j'ai téléchargé deuxième échantillon à bash complexe bonjour tout le monde, ce script prend environ 0.72 sec pour terminer sur mon hôte.
J'ai ajouter en haut du script:
en elap.bash fonction
#!/bin/bash
source elap.bash-v2 trap2
eval "BUNCHS=(" $(perl <<EOF | gunzip
...
en set -x et PS4
#!/bin/bash
PS4='+ $(date "+%s.%N")\011 '
exec 3>&2 2>/tmp/bashstart.$$.log
set -x
eval "BUNCHS=(" $(perl <<EOF | gunzip
...
en set -x et initiale de la fourche à long commande exec
#!/bin/bash
exec 3>&2 2> >(tee /tmp/sample-time.$$.log |
sed -u 's/^.*$/now/' |
date -f - +%s.%N >/tmp/sample-time.$$.tim)
set -x
eval "BUNCHS=(" $(perl <<EOF | gunzip
Et de comparer le temps d'exécution (sur ma machine):
en elap.bash fonction
0.000950277 0.000950277 Starting
0.007618964 0.008569241 eval "BUNCHS=(" $(perl <<EOF | gunzi
0.005259953 0.013829194 BUNCHS=("2411 1115 -13 15 33 -3 15 1
0.010945070 0.024774264 MKey="V922/G/,2:"
0.001050990 0.025825254 export RotString=""
0.004724348 0.030549602 initRotString
0.001322184 0.031871786 for bunch in "${BUNCHS[@]}"
0.000768893 0.032640679 out=""
0.001008242 0.033648921 bunchArray=($bunch)
0.000741095 0.034390016 ((k=0))
en set -x et PS4
++ 1388598366.536099290 perl
++ 1388598366.536169132 gunzip
+ 1388598366.552794757 eval 'BUNCHS=(' '"2411' 1115 -13 15 33 -3 15 1
++ 1388598366.555001983 BUNCHS=("2411 1115 -13 15 33 -3 15 13111 -6 1
+ 1388598366.557551018 MKey=V922/G/,2:
+ 1388598366.558316839 export RotString=
+ 1388598366.559083848 RotString=
+ 1388598366.560165147 initRotString
+ 1388598366.560942633 local _i _char
+ 1388598366.561706988 RotString=
en set -x et initiale de la fourche à long commande exec (et mon second paste exemple de script)
0.000000000 0.000000000 ++ perl
0.008141159 0.008141159 ++ gunzip
0.000007822 0.008148981 + eval 'BUNCHS=(' '"2411' 1115 -13 15 33 -3
0.000006216 0.008155197 ++ BUNCHS=("2411 1115 -13 15 33 -3 15 13111
0.000006216 0.008161413 + MKey=V922/G/,2:
0.000006076 0.008167489 + export RotString=
0.000006007 0.008173496 + RotString=
0.000006006 0.008179502 + initRotString
0.000005937 0.008185439 + local _i _char
0.000006006 0.008191445 + RotString=
en strace
0.000213 0.000213 brk(0) = 0x17b6000
0.000044 0.000257 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000047 0.000304 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faf1c0dc000
0.000040 0.000344 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000040 0.000384 open("/etc/ld.so.cache", O_RDONLY) = 4
...
0.000024 4.425049 close(10) = 0
0.000042 4.425091 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
0.000028 4.425119 read(255, "", 4409) = 0
0.000058 4.425177 exit_group(0) = ?
Bien! Si mon pur bash est plus rapide que la bifurcation pour la date sur chaque commande, mon pur bash implie certaines opérations sur chaque commande.
La façon de consacrer un processus indépendant pour l'enregistrement et le stockage est nettement plus efficace.
strace est une façon intéressante, la plus détaillée, mais difficile à lire.
Finalement, je pense que le plus efficace, dans la lisibilité et de spectacles, est set + 1 fork, La première de cette réponse.
Il est souvent utile de suivre les appels système
strace -c -f ./script.sh
Du manuel:
-c Compter le temps, les appels et les erreurs pour chaque appel système et générer un récapitulatif à la sortie du programme.
-f Trace les processus enfants ...
Ce n'est pas exactement ce que vous voulez et ce qu'un profileur orienté ligne vous montrerait, mais cela aide généralement à trouver des points chauds.
Temps, xtrace, bash -x, set -x et set+x (http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.htmlrestent les orthodoxes façon de déboguer un script.
Cependant afin d'élargir notre horizon, il est possible de donner un chèque à un système pour le débogage et le profilage disponibles pour l'habituel programmes Linux [ici l'une des listes], par exemple, il devrait en résulter utile basé sur valgrind en particulier à la mémoire de débogage ou de sysprof de profil de l'ensemble du système:
Pour sysprof:
Avec sysprof, vous pouvez le profil de toutes les applications en cours d'exécution sur votre machine, y compris un multithread ou multiprocessed application...
Et après pour sélectionner la direction générale de la sous-processus que vous trouvez intéressant.
Pour Valgrind:
Avec un peu plus de sport, il semble qu'il est possible de rendre visible à Valgrind certains programmes qui, habituellement, nous faisons l'installation des binaires (par exemple, OpenOffice).
Il est possible de lire la FAQ de valgrind qu' Valgrind sera le profil de l' enfant, les processus si explicitement demandé.
... Même si par défaut, les profils des traces seulement le haut niveau des processus, et alors si votre programme est lancé par un script shell, Perl, script, ou quelque chose de similaire, Valgrind trace de la coquille, ou de l'interpréteur Perl, ou équivalent...
Il le fera avec cette option activée
--trace-children=yes
Références Supplémentaires:
Prograide est une communauté de développeurs qui cherche à élargir la connaissance de la programmation au-delà de l'anglais.
Pour cela nous avons les plus grands doutes résolus en français et vous pouvez aussi poser vos propres questions ou résoudre celles des autres.
