Comment profiler un démarrage lent d'un script shell bash?

124

Mon shell bash prend jusqu'à 3-4 secondes pour démarrer, tandis que si je le démarre avec, --norcil s'exécute immédiatement.

J'ai commencé à "profiler" /etc/bash.bashrcet ~/.bashrcen insérant manuellement des returndéclarations et en cherchant des améliorations de vitesse, mais ce n'est pas un processus quantitatif et ce n'est pas efficace.

Comment puis-je profiler mes scripts bash et voir quelles commandes prennent le plus de temps à démarrer?

bash profiling Andrea Spadaccini
la source
3
J'ai profilé les scripts, et la plupart du temps a été passé lors de la configuration de bash_completion.
Andrea Spadaccini
1
Ce n'est pas surprenant puisque c'est assez gros. Vous pouvez accélérer cela en supprimant les parties dont vous savez que vous n'aurez jamais besoin si vous voulez vous donner la peine de maintenir vos modifications à travers les mises à jour, etc.
pause jusqu'à nouvel ordre.
2
Vous pouvez comparer: time bash -c 'exit'et time bash -i -c 'exit'et jouer avec --norcet --noprofile.
F.Hauri
Voir aussi cette réponse (avertissement: c'est le mien). Pas exactement ce que vous demandez, mais certainement lié: unix.stackexchange.com/a/555510/384864
Johan Walles

Réponses:

128

Si vous avez GNU date(ou une autre version qui peut générer des nanosecondes), faites-le au début de /etc/bash.bashrc(ou à l'endroit où vous souhaitez commencer une trace dans n'importe quel 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 ~/.bashrc(ou à la fin de la section de tout script Bash que vous souhaitez que le traçage arrête). Le \011est un caractère de tabulation octal.

Vous devriez obtenir un journal de /tmp/bashstart.PID.logsuivi qui affiche l'horodatage en secondes.nanosecondes de chaque commande exécutée. La différence d'une fois à l'autre est la durée de l'étape intermédiaire.

Au fur et à mesure que vous affinez les choses, vous pouvez vous déplacer de set -xplus en plus set +xtôt (ou entre parenthèses plusieurs sections d'intérêt de manière sélective).

Bien qu'il ne soit pas aussi fin que dateles nanosecondes de GNU , Bash 5 inclut une variable qui donne le temps en microsecondes. Son utilisation vous évite de créer un exécutable externe pour chaque ligne et fonctionne sur des Mac ou ailleurs qui n'ont pas GNU date- tant que vous avez Bash 5, bien sûr. Modifiez le paramètre de PS4:

PS4='+ $EPOCHREALTIME\011 '

Comme indiqué par @pawamoy, vous pouvez utiliser BASH_XTRACEFDpour envoyer la sortie de la trace vers un descripteur de fichier séparé si vous avez Bash 4.1 ou version ultérieure. De cette réponse :

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

Cela entraînera la sortie de la trace vers le fichier command.txtsortant stdoutet stdoutsera sortie normalement (ou sera redirigée séparément).

Suspendu jusqu'à nouvel ordre.
la source
Est-il normal que l'invite du shell soit invisible et que mes commandes ne soient pas renvoyées en écho? Cependant, j'ai obtenu la trace pour pouvoir commencer l'analyse .. merci beaucoup!
Andrea Spadaccini
1
@AndreaSpadaccini: La finale execdevrait renvoyer fd2 à la normale, vous devriez donc récupérer l'invite.
Suspendu jusqu'à nouvel ordre.
7
... en fait, avec bash 4.2, on peut faire mieux - l'utilisation de \D{...}in PS4permet d'étendre des chaînes de format de temps complètement arbitraires sans la surcharge de performances du lancement en datetant que sous-processus.
Charles Duffy
3
@CharlesDuffy: Ce sont tous les deux vraiment cool. Cependant GNU datecomprend %Net Bash 4.2 ne le fait pas (parce strftime(3)que non) sur le système GNU - donc arbitraire avec des limites. Votre point de vue sur les performances par rapport à la résolution est bon et un utilisateur doit faire un choix judicieux, en gardant à l'esprit que l'atteinte des performances est temporaire uniquement pendant le débogage (et uniquement lorsqu'elle set -xest en vigueur).
Suspendu jusqu'à nouvel ordre.
1
Avec Bash 4, on peut également utiliser la variable BASH_XTRACEFD pour rediriger la sortie de débogage vers un autre descripteur de fichier que celui par défaut (2, ou stderr). Cela aide énormément quand vient le temps d'analyser la sortie (les données de profilage), car il n'est plus nécessaire de démêler stderr et de définir la sortie -x (autant de cas de bord).
pawamoy
107

Profilage frapper (4 réponses)

Edit:script méthode d' ajout de mars 2016

En lisant ceci et parce que le profilage est une étape importante, j'ai fait des tests et des recherches sur toute cette question SO et j'ai déjà publié des réponses.

Il y a 4+ réponses:

  • Le premier est basé sur l'idée de @ DennisWilliamson mais avec beaucoup moins de consommation de ressources
  • Le second était le mien (avant ça;)
  • Le troisième est basé sur la réponse @fgm, mais plus précis.

  • La dernière utilisation script, scriptreplayet le fichier de synchronisation .

  • Enfin, un petit comparatif des performances à la fin.

Utilisation set -xet datemais avec des fourches limitées

Reprenez l'idée de @ DennisWilliamson, mais avec la syntaxe suivante, il n'y aura qu'un seul fork initial pour 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

Cela ne fonctionnera datequ'une seule fois. Il existe une démonstration / test rapide pour montrer comment cela 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 créez 2 fichiers: /tmp/sample-XXXX.loget /tmp/sample-XXXX.tim(où XXXX est l'identifiant de processus du script en cours d'exécution).

Vous pouvez les présenter en utilisant paste:

paste tmp/sample-XXXX.{tim,log}

Ou vous pouvez même calculer le temps de différence:

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 rendre:

 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

Utilisation de trap debuget /proc/timer_listsur les noyaux GNU / Linux récents , sans fourches .

Sous les noyaux récents de GNU / Linux , vous pouvez trouver un /procfichier 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 de 5461935212966259 + 1383718821564493249, mais en nanosecondes.

Donc, pour calculer le temps écoulé , il n'est pas nécessaire de connaître le décalage.

Pour ce genre d'emplois, j'ai écrit elap.bash (V2) , qui provient de la syntaxe suivante:

source elap.bash-v2

ou

. elap.bash-v2 init

(Voir les commentaires pour la syntaxe complète)

Vous pouvez donc simplement 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 mon hôte:

 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

Utilisation trap2au lieu de trapcomme argument de la commande source:

#!/bin/bash

. elap.bash-v2 trap2
...

Affiche la dernière commande et le total de deux colonnes :

 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

En utilisant strace

Oui, stracepourrait faire le travail:

strace -q -f -s 10 -ttt sample-script 2>sample-script-strace.log

Mais il pourrait y avoir beaucoup de choses!

wc sample-script-strace.log
    6925  57637 586518 sample-script-strace.log

Utilisation d'une commande plus restreinte:

strace -f -s 10 -ttt -eopen,access,read,write ./sample-script 2>sample-script-strace.log

Videra le journal plus léger:

  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

Leur 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) ---

Le script bash original n'est pas si facile à suivre dans ce cas ...

L' utilisation script, scriptreplayet le fichier de synchronisation

Dans le cadre de BSD Utils , script(and scriptreplay) est un outil très ancien qui peut être utilisé pour profiler bash, avec un très faible encombrement.

script -t script.log 2>script.tim -c 'bash -x -c "
    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
"'

Produira:

Script started on Fri Mar 25 08:29:37 2016
+ (( i=3 ))
+ (( i-- ))
+ sleep .1
+ (( 1 ))
+ (( i-- ))
+ sleep .1
+ (( 1 ))
+ (( i-- ))
+ sleep .1
+ (( 1 ))
+ (( i-- ))
+ (( i=2 ))
+ (( i-- ))
+ tar -cf /tmp/test.tar -C / bin
+ gzip /tmp/test.tar
+ rm /tmp/test.tar.gz
+ (( 1 ))
+ (( i-- ))
+ tar -cf /tmp/test.tar -C / bin
+ gzip /tmp/test.tar
+ rm /tmp/test.tar.gz
+ (( 1 ))
+ (( i-- ))
Script done on Fri Mar 25 08:29:39 2016

et générez deux fichiers:

ls -l script.*
-rw-r--r-- 1 user user 450 Mar 25 08:29 script.log
-rw-r--r-- 1 user user 177 Mar 25 08:29 script.tim

Le fichier script.logcontient toutes les traces et script.timest le fichier de synchronisation :

head -n 4 script.*
==> script.log <==
Script started on Fri Mar 25 08:29:37 2016
+ (( i=3 ))
+ (( i-- ))
+ sleep .1

==> script.tim <==
0.435331 11
0.000033 2
0.000024 11
0.000010 2

Vous pouvez voir l'exécution du temps total avec les première et dernière lignes du fichier journal et / ou en résumant les temps dans le fichier de synchronisation:

head -n1 script.log ;tail -n1 script.log 
Script started on Fri Mar 25 08:29:37 2016
Script done on Fri Mar 25 08:29:39 2016

sed < script.tim  's/ .*$//;H;${x;s/\n/+/g;s/^\+//;p};d' | bc -l
2.249755

Dans le fichier de synchronisation, la deuxième valeur est le nombre d'octets suivants dans le fichier journal correspondant. Cela vous permet de rejouer le fichier journal en option avec un facteur d'accélération :

scriptreplay script.{tim,log}

ou

scriptreplay script.{tim,log} 5

ou

 scriptreplay script.{tim,log} .2

Afficher les heures et les commandes côte à côte est également un peu plus complexe:

exec 4<script.log
read -u 4 line
echo $line ;while read tim char;do
    read -u 4 -N $char -r -s line
    echo $tim $line
  done < script.tim &&
while read -u 4 line;do
    echo $line
done;exec 4<&-
Script started on Fri Mar 25 08:28:51 2016
0.558012 + (( i=3 ))
0.000053 
0.000176 + (( i-- ))
0.000015 
0.000059 + sleep .1
0.000015 
 + sleep .1) + (( 1 ))
 + sleep .1) + (( 1 ))
 + tar -cf /tmp/test.tar -C / bin
0.035024 + gzip /tmp/test.tar
0.793846 + rm /tmp/test.tar.gz
 + tar -cf /tmp/test.tar -C / bin
0.024971 + gzip /tmp/test.tar
0.729062 + rm /tmp/test.tar.gz
 + (( i-- )) + (( 1 ))
Script done on Fri Mar 25 08:28:53 2016

Tests et conclusion

Pour faire des tests, j'ai téléchargé un deuxième exemple sur bash complex hello world , ce script prend environ 0,72 sec pour se terminer sur mon hôte.

J'ai ajouté en haut du script l'un des:

  • par elap.bashfonction

    #!/bin/bash

source elap.bash-v2 trap2

eval "BUNCHS=(" $(perl <<EOF | gunzip
...

  • par set -xetPS4

    #!/bin/bash

PS4='+ $(date "+%s.%N")\011 '
exec 3>&2 2>/tmp/bashstart.$$.log
set -x

eval "BUNCHS=(" $(perl <<EOF | gunzip
...

  • par set -xet initialisation de la commande d'exécution longue

    #!/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

  • par script(et set +x)

    script -t helloworld.log 2>helloworld.tim -c '
    bash -x complex_helloworld-2.sh' >/dev/null

Fois

Et comparez les temps d'exécution (sur mon hôte):

  • Direct 0,72 s
  • elap.bash 13,18 sec
  • set + date @ PS4 54,61 sec
  • set + 1 fourchette 1,45 sec
  • script et fichier de synchronisation 2.19 sec
  • strace 4,47 sec

Les sorties

  • par elap.bashfonction

         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))

  • par set -xetPS4

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

  • par set -xet initialiser le fork à la commande d'exécution longue (et mon deuxième pasteexemple 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=

  • par 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)         = ?

  • par script

    Le script a débuté sur ven 25 mar 2016 09:18:35 CET
0.667160 ++ gunzip
0.000025 
0.000948 ++ perl
0.000011 
0.005338 + eval 'BUNCHS=(' '"2411' 1115 -13 15 33 -3 15 13111 -6 1 111 4
0.000044 1223 15 3311 121121 17 3311 121121 1223 3311 121121 17 3311 121
0.000175 ++ BUNCHS=("2411 1115 -13 15 33 -3 15 13111 -6 15 1114 15 12211
0.000029 1 1321 12211 412 21211 33 21211 -2 15 2311 11121 232 121111 122
0.000023 4 3311 121121 12221 3311 121121 12221 3311 121121 1313 -6 15 33

Conclusion

Bien! Si mon pur bash est plus rapide que le forking à ce jour sur chaque commande , mon pur bash implique quelques opérations sur chaque commande.

La manière de consacrer un processus indépendant pour la journalisation et le stockage est clairement plus efficace.

strace est une manière intéressante, plus détaillée, mais difficile à lire.

script, avec scriptreplayet facteur d'accélération est très sympa aussi, pas la même précision car cela est basé sur l'échange de console au lieu de l'exécution de processus, mais très léger et efficace (pas le même objectif, pas le même usage).

Enfin, je pense que le plus efficace, en lisibilité et en performances, c'est set + 1 fork, le premier de cette réponse, mais in fine, selon le cas particulier, j'utilise parfois straceet / ou scriptaussi.

F. Hauri
la source
2
Ceci a été publié sur Unix & Linux - Comment ajuster la commande de temps pour mesurer le temps écoulé d'un programme
F.Hauri
2
La section Times est assez informative et montre que les fourches ne sont pas à éternuer (en effet, elles dominent complètement de nombreux types de scripts). +1 pour une bonne réponse (si longue). Peut-être à l'avenir , vous devriez envisager d' afficher des réponses distinctes
sehe
1
Merci beaucoup, @sehe! Vous y trouverez un fichier source bash complet prêt à l' emploi : elap-bash-v3 (avec des fonctionnalités telles que permettre l'utilisation transparente de STDIN et STDERR )
F.Hauri
1
Sur les versions récentes de bash (> = 4.1), vous pouvez faire à la exec {BASH_XTRACEFD}>place de exec 3>&2 2>qui ne remplira le fichier journal qu'avec la sortie de journalisation de trace et pas une autre sortie stderr.
ws_e_c421
1
La méthode de traitement exécutable à une date unique est très intelligente et ma préférence pour une précision inférieure à la seconde. Car script.sh, je peux simplement faire bash -c "exec {BASH_XTRACEFD}> >(tee trace.log | sed -u 's/^.*$//' | date -f - +%s.%N > timing.log); set -x; . script.shet obtenir des données de profilage sans les modifier script.sh. Quand une précision inférieure à la seconde n'est pas nécessaire, j'aime bash -c "exec {BASH_XTRACEFD}>trace.log; set -x; PS4='+\t'; . script.shquel horodatage chaque ligne de trace avec une seconde précision et sans bifurcation à la date (faible surcharge).
ws_e_c421
17

Il aide souvent à retracer les appels système

strace -c -f ./script.sh

À partir du manuel:

-c Compter le temps, les appels et les erreurs pour chaque appel système et rapporter un résumé à la sortie du programme.

-f Tracer 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.

Fritz G. Mehner
la source
5

Vous pouvez consulter la trapcommande avec la condition DEBUG . Il existe un moyen de définir une ou plusieurs commandes à exécuter avec vos commandes. Voir les notes de la réponse.


la source
@Dennis Williamson: Je ne l'ai pas utilisé depuis un moment, mais l'aide sur mon système indique que "Si un SIGNAL_SPEC est DEBUG, ARG est exécuté après chaque commande simple."
De Bash 4.0.33 help trap: "Si un SIGNAL_SPEC est DEBUG, ARG est exécuté avant chaque commande simple." Dans Bash 3.2, il dit "après". C'est une faute de frappe. Depuis Bash 2.05b, il est déjà exécuté. Référence : "Ce document détaille les changements entre cette version, bash-2.05b-alpha1, et la version précédente, bash-2.05a-release. ... 3. Nouvelles fonctionnalités de Bash ... w. Le trap DEBUG est maintenant s'exécute avant les commandes simples, les ((...)) commandes, [...] les commandes conditionnelles et les boucles for ((...)). " Le test dans chaque version confirme que c'est avant .
Suspendu jusqu'à nouvel ordre.
@Dennis Williamson: Ok, alors c'est la version que j'ai. Je corrige la réponse :)
0

Time, xtrace, bash -x set -xet set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html ) restent la méthode classique pour déboguer un script.

Toujours pour élargir notre horizon, il est possible de donner un contrôle à un système pour le débogage et le profilage disponible pour les programmes Linux habituels [ici une des listes] , par exemple il devrait en résulter un utile basé sur valgrind en particulier pour déboguer la mémoire ou sysprof pour profil l'ensemble du système:

Pour sysprof:

Avec sysprof, vous pouvez profiler toutes les applications qui s'exécutent sur votre machine, y compris une application multithread ou multiprocessus ...

Et après pour sélectionner la branche de sous-processus que vous trouvez intéressante.

Pour Valgrind:
Avec un peu plus de gym, il semble possible de rendre visibles à Valgrind certains programmes que nous installons habituellement à partir de binaires (par exemple OpenOffice ).

Il est possible de lire la FAQ de valgrind qui Valgrindprofilera les processus enfants si cela est explicitement demandé.

... Même si, par défaut, le profil ne trace que le processus de niveau supérieur, et donc si votre programme est démarré par un script shell , un script Perl ou quelque chose de similaire, Valgrind tracera le shell, ou l'interpréteur Perl, ou équivalent. ..

Il le fera avec cette option activée 

 --trace-children=yes

Références supplémentaires:

  • Manuel Valgrind .
  • Quelques nouvelles sur les interfaces KCachegrind et Callgrind ou aussi ici , toujours utilisées comme rapporté sur un wiki du CERN
  • manuel gdb . pour gdb qui peut être utile pour profiler c, programme c ++ appelé par le script.
Hastur
la source
1
Pas le downvoter, mais la plupart de ces conseils, bien que cool, ne sont pas vraiment pertinents ici. Poser une question appropriée et y répondre par vous-même est plus bienvenue ici - Google "stackoverflow self reponses" pour l'étiquette appropriée.
Blaisorblade
0

Cet article d' Alan Hargreaves décrit la méthode de profilage du script Bourne shell à l'aide du fournisseur DTrace. Autant que je sache, cela fonctionne avec Solaris et OpenSolaris (voir: / bin / sh DTrace Provider ).

Donc, étant donné le script dtrace suivant ( sh_flowtime.dà GH basé sur l' original ):

#!/usr/sbin/dtrace -Zs
#pragma D option quiet
#pragma D option switchrate=10

dtrace:::BEGIN
{
        depth = 0;
        printf("%s %-20s  %-22s   %s %s\n", "C", "TIME", "FILE", "DELTA(us)", "NAME");
}

sh*:::function-entry
{
        depth++;
        printf("%d %-20Y  %-22s %*s-> %s\n", cpu, walltimestamp,
            basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
}

sh*:::function-return
{
        printf("%d %-20Y  %-22s %*s<- %s\n", cpu, walltimestamp,
            basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
        depth--;
}

sh*:::builtin-entry
{
        printf("%d %-20Y  %-22s %*s   > %s\n", cpu, walltimestamp,
            basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
}

sh*:::command-entry
{
        printf("%d %-20Y  %-22s %*s   | %s\n", cpu, walltimestamp,
            basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
}

vous pouvez suivre le flux des fonctions, y compris les temps delta.

Exemple de sortie:

# ./sh_flowtime.d
C TIME                  FILE                 DELTA(us)  -- NAME
0 2007 Aug 10 18:52:51  func_abc.sh                  0   -> func_a
0 2007 Aug 10 18:52:51  func_abc.sh                 54      > echo
0 2007 Aug 10 18:52:52  func_abc.sh            1022880      | sleep
0 2007 Aug 10 18:52:52  func_abc.sh                 34     -> func_b
0 2007 Aug 10 18:52:52  func_abc.sh                 44        > echo
0 2007 Aug 10 18:52:53  func_abc.sh            1029963        | sleep
0 2007 Aug 10 18:52:53  func_abc.sh                 44       -> func_c
0 2007 Aug 10 18:52:53  func_abc.sh                 43          > echo
0 2007 Aug 10 18:52:54  func_abc.sh            1029863          | sleep
0 2007 Aug 10 18:52:54  func_abc.sh                 33       <- func_c
0 2007 Aug 10 18:52:54  func_abc.sh                 14     <- func_b
0 2007 Aug 10 18:52:54  func_abc.sh                  7   <- func_a

Ensuite, à l'aide de la sort -nrk7commande, vous pouvez trier la sortie pour afficher les appels les plus consommateurs.

Je ne connais aucun fournisseur de sondes disponibles pour d'autres shells, alors faites des recherches (recherche sur GitHub?) Ou si vous souhaitez investir du temps, vous pouvez les écrire en vous basant sur l' exemple sh existant : (voir: Comment activer sh Fournisseur DTrace? ).

Kenorb
la source