Der Start meiner Bash-Shell dauert bis zu 3-4 Sekunden. Wenn ich sie --norcdamit starte, wird sie sofort ausgeführt.

Ich habe mit dem "Profiling" begonnen /etc/bash.bashrcund Anweisungen ~/.bashrcmanuell eingefügt returnund nach Geschwindigkeitsverbesserungen gesucht, aber es ist kein quantitativer Prozess und nicht effizient.

Wie kann ich meine Bash-Skripte profilieren und sehen, welche Befehle am meisten Zeit zum Starten benötigen?

Wenn Sie über GNU date(oder eine andere Version, die Nanosekunden ausgeben kann) verfügen, tun Sie dies zu Beginn von /etc/bash.bashrc(oder wo immer Sie eine Ablaufverfolgung in einem Bash-Skript beginnen möchten):

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

hinzufügen

set +x
exec 2>&3 3>&-

am Ende ~/.bashrc(oder am Ende des Abschnitts eines Bash-Skripts, dessen Ablaufverfolgung beendet werden soll). Das \011ist ein oktales Tabulatorzeichen.

Sie sollten ein Ablaufverfolgungsprotokoll erhalten /tmp/bashstart.PID.log, das den Zeitstempel von Sekunden und Nanosekunden jedes ausgeführten Befehls anzeigt. Der Unterschied von einem Zeitpunkt zum nächsten ist die Zeit, die der dazwischenliegende Schritt benötigt hat.

Wenn Sie die Dinge eingrenzen, können Sie sich set -xspäter und set +xfrüher bewegen (oder mehrere Abschnitte von Interesse selektiv einklammern).

Obwohl es nicht so feinkörnig ist wie datedie Nanosekunden von GNU , enthält Bash 5 eine Variable, die die Zeit in Mikrosekunden angibt. Die Verwendung erspart Ihnen das Laichen einer externen ausführbaren Datei für jede Zeile und funktioniert auf Macs oder anderen Geräten ohne GNU date- solange Sie natürlich über Bash 5 verfügen. Ändern Sie die Einstellung von PS4:

PS4='+ $EPOCHREALTIME\011 '

Wie von @pawamoy hervorgehoben, können Sie BASH_XTRACEFDdie Ausgabe des Trace an einen separaten Dateideskriptor senden, wenn Sie über Bash 4.1 oder höher verfügen. Aus dieser Antwort :

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

Dadurch wird die Trace - Ausgabe in die Datei gehen command.txtverlassen stdoutund stdoutausgegeben wird normalerweise (oder separat umgeleitet werden).

Profilerstellung Bash (4 Antworten)

Bearbeiten: März 2016script Methode hinzufügen

Lesen Sie dies und da die Profilerstellung ein wichtiger Schritt ist, habe ich einige Tests und Nachforschungen zu dieser gesamten SO-Frage durchgeführt und bereits Antworten veröffentlicht.

Es gibt 4+ Antworten:

• Die erste basiert auf der Idee von @ DennisWilliamson, verbraucht jedoch viel weniger Ressourcen
• Der zweite war mein eigener (vorher;)
• Die dritte basiert auf der @ fgm-Antwort, ist aber genauer.

• Der letzte Einsatz script, scriptreplayund Timing - Datei .

• Zum Schluss noch ein kleiner Leistungsvergleich.

Verwenden set -xund dateaber mit begrenzten Gabeln

Nehmen Sie von der Idee von @ DennisWilliamson, aber mit der folgenden Syntax gibt es nur eine anfängliche Verzweigung zu 3 Befehlen:

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

Dies wird datenur einmal ausgeführt. Es gibt eine kurze Demo / einen Test, um zu zeigen, wie es funktioniert:

for i in {1..4};do echo now;sleep .05;done| date -f - +%N

Beispielskript:

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

Durch Ausführen dieses Skripts erstellen Sie zwei Dateien: /tmp/sample-XXXX.logund /tmp/sample-XXXX.tim(wobei XXXX die Prozess-ID des ausgeführten Skripts ist).

Sie können sie präsentieren mit paste:

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

Oder Sie können sogar die Diff-Zeit berechnen:

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

oder auf zwei Spalten:

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

Darf rendern:

 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

Verwenden trap debugund /proc/timer_listauf aktuellen GNU / Linux-Kerneln ohne Gabeln .

Unter den neuesten Kerneln von GNU / Linux finden Sie möglicherweise eine /procDatei mit dem Namen timer_list:

grep 'now at\|offset' /proc/timer_list
now at 5461935212966259 nsecs
  .offset:     0 nsecs
  .offset:     1383718821564493249 nsecs
  .offset:     0 nsecs

Wobei die aktuelle Zeit die Summe von 5461935212966259 + 1383718821564493249, aber in Nanosekunden ist.

Für die Berechnung der verstrichenen Zeit ist es daher nicht erforderlich, den Offset zu kennen.

Für diese Art von Jobs habe ich elap.bash (V2) geschrieben , die mit der folgenden Syntax bezogen werden:

source elap.bash-v2

oder

. elap.bash-v2 init

(Siehe Kommentare für die vollständige Syntax)

Sie können also einfach diese Zeile oben in Ihr Skript einfügen:

. elap.bash-v2 trap2

Kleine Probe:

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

Rendern Sie auf meinem Host:

 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

Verwenden Sie trap2anstelle von trapals Argument für den Quellbefehl:

#!/bin/bash

. elap.bash-v2 trap2
...

Rendert zwei Spalten als letzten Befehl und als Summe :

 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

Verwenden von strace

Ja, stracekönnte den Job machen:

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

Aber es könnte eine Menge Zeug machen!

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

Verwenden eines eingeschränkteren Befehls:

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

Wird leichteres Holz wegwerfen:

  4519  36695 374453 sample-script-strace.log

Je nachdem, wonach Sie suchen, sind Sie möglicherweise restriktiver:

 strace -f -s 10 -ttt -eaccess,open ./sample-script 2>&1 | wc
  189    1451   13682

Es wird etwas schwieriger sein, sie zu lesen:

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

Das ursprüngliche Bash-Skript ist in diesem ...

Unter Verwendung script, scriptreplayund Timing - Datei

Als Teil von BSD Utils ist script(und scriptreplay) ein sehr altes Tool, mit dem Bash mit sehr geringem Platzbedarf profiliert werden kann.

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
"'

Wird herstellen:

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

und generieren Sie zwei Dateien:

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

Datei script.logenthält alle Spuren und script.timist die Timing-Datei :

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

Sie können die Gesamtzeitausführung mit der ersten und letzten Zeile der Protokolldatei und / oder durch Zusammenfassen der Zeiten in der Zeitdatei anzeigen:

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

In der Timing-Datei ist der zweite Wert die Anzahl der nächsten Bytes in der entsprechenden Protokolldatei. Dies können Sie die Fähigkeit der Wiedergabe von Protokolldatei optional mit einem Beschleunigungsfaktor :

scriptreplay script.{tim,log}

oder

scriptreplay script.{tim,log} 5

oder

 scriptreplay script.{tim,log} .2

Das Anzeigen von Zeiten und Befehlen nebeneinander ist ebenfalls etwas komplexer:

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 und Schlussfolgerung

Um Tests durchzuführen, habe ich das zweite Beispiel bei Bash Complex Hello World heruntergeladen. Die Ausführung dieses Skripts auf meinem Host dauert ca. 0,72 Sekunden.

Ich habe oben im Skript Folgendes hinzugefügt:

• nach elap.bashFunktion

  #!/bin/bash
  
  source elap.bash-v2 trap2
  
  eval "BUNCHS=(" $(perl <<EOF | gunzip
  ...

• von set -xundPS4

  #!/bin/bash
  
  PS4='+ $(date "+%s.%N")\011 '
  exec 3>&2 2>/tmp/bashstart.$$.log
  set -x
  
  eval "BUNCHS=(" $(perl <<EOF | gunzip
  ...

• by set -xund Initial Fork to Long Exec Befehl

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

• von script(und set +x)

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

Mal

Und vergleichen Sie die Ausführungszeiten (auf meinem Host):

• Direkt 0,72 Sek
• elap.bash 13,18 Sek
• setze + Datum @ PS4 54,61 Sek
• + 1 Gabel einstellen 1,45 Sek
• Skript- und Timing-Datei 2.19 Sek
• strace 4,47 sek

Ausgänge

• nach elap.bashFunktion

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

• von set -xundPS4

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

• by set -xund initial fork to long exec befehl (und mein zweites beispielskript paste)

   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=

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

• durch 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

Fazit

Gut! Wenn meine reine Bash bei jedem Befehl schneller ist als das bisherige Gabeln, impliziert meine reine Bash einige Operationen für jeden Befehl.

Die Art und Weise, einen unabhängigen Prozess für die Protokollierung und Speicherung einzurichten, ist deutlich effizienter.

strace ist ein interessanter Weg, detaillierter, aber schwer zu lesen.

script, mit scriptreplayund Beschleunigungsfaktor ist auch sehr schön, nicht die gleiche Präzision wie diese basiert auf Konsolenaustausch anstelle von Prozessausführung, aber sehr leicht und effizient (nicht das gleiche Ziel, nicht die gleiche Verwendung).

Schließlich denke ich, dass die effizientere Lesbarkeit und Leistung set + 1 forkdie erste dieser Antwort ist, aber in Ordnung, je nach Einzelfall, verwende ich sie irgendwann straceund / oder scriptauch.

Es ist oft hilfreich, die Systemaufrufe zu verfolgen

strace -c -f ./script.sh

Aus dem Handbuch:

-c Zählen Sie Zeit, Aufrufe und Fehler für jeden Systemaufruf und melden Sie eine Zusammenfassung beim Beenden des Programms.

-f Untergeordnete Prozesse verfolgen ...

Dies ist nicht genau das, was Sie wollen und was ein linienorientierter Profiler Ihnen zeigen würde, aber es hilft normalerweise, Hotspots zu finden.

Sie können sich den trapBefehl mit der DEBUG- Bedingung ansehen . Es gibt eine Möglichkeit, einen oder mehrere Befehle festzulegen, die zusammen mit Ihren Befehlen ausgeführt werden sollen. Siehe die Anmerkungen zur Antwort.

Time, xtrace, bash -x set -xund set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html ) bleiben die orthodoxe Methode zum Debuggen eines Skripts.

Um unseren Horizont zu erweitern, ist es dennoch möglich, ein System zum Debuggen und Profilieren zu überprüfen, das für die üblichen Linux-Programme verfügbar ist [hier eine der Listen] , z. B. sollte es ein nützliches System sein , das auf valgrind basiert, insbesondere um Speicher oder sysprof to profile zu debuggen das ganze System:

Für sysprof:

Mit sysprof können Sie alle Anwendungen profilieren, die auf Ihrem Computer ausgeführt werden, einschließlich einer Multithread- oder Multiprozessor-Anwendung ...

Und danach wählen Sie den Zweig der Unterprozesse aus, die Sie interessant finden.

Für Valgrind:
Mit etwas mehr Fitnessstudio scheint es möglich zu sein, Valgrind einige Programme sichtbar zu machen , die wir normalerweise über Binärdateien installieren (z . B. OpenOffice ).

Es ist möglich , aus dem lesen FAQ von valgrind , die Valgrinddie wird das Profil Kind - Prozesse , wenn explizit angefordert.

... Auch wenn standardmäßig nur der Prozess der obersten Ebene profiliert wird. Wenn Ihr Programm also von einem Shell-Skript , Perl-Skript oder ähnlichem gestartet wird , verfolgt Valgrind die Shell oder den Perl-Interpreter oder ein gleichwertiges Programm . ..

Dies wird bei aktivierter Option durchgeführt

 --trace-children=yes 

Zusätzliche Referenzen:

• Valgrind Handbuch.
• Einige Neuigkeiten über die Schnittstellen KCachegrind und Callgrind oder auch hier , die noch verwendet werden, wie aus einem Wiki des CERN berichtet
• GDB- Handbuch. für gdb , das für das Profil c nützlich sein kann, c ++ - Programm, das vom Skript aufgerufen wird.

Dieser Beitrag von Alan Hargreaves beschreibt die Methode zum Profilieren des Bourne-Shell-Skripts mithilfe des DTrace-Anbieters. Soweit ich weiß, funktioniert dies mit Solaris und OpenSolaris (siehe: / bin / sh DTrace Provider ).

Geben Sie also das folgende dtrace-Skript an ( sh_flowtime.dbei GH basierend auf dem 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));
}

Sie können den Funktionsfluss einschließlich der Deltazeiten verfolgen.

Beispielausgabe:

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

Dann mit sort -nrk7 Befehl die Ausgabe sortieren, um die am meisten konsumierenden Anrufe anzuzeigen.

Mir sind keine Anbietersonden bekannt, die für andere Shells verfügbar sind. Machen Sie also einige Nachforschungen (GitHub-Suche?) Oder wenn Sie etwas Zeit investieren möchten, können Sie diese anhand des vorhandenen sh- Beispiels schreiben : (siehe: So aktivieren Sie sh DTrace-Anbieter? ).