Moja powłoka bash uruchamia się do 3-4 sekund, a jeśli ją uruchomię --norc, działa natychmiast.

Zacząłem „profilować” /etc/bash.bashrci ~/.bashrcręcznie wstawiać returnstwierdzenia i szukać ulepszeń szybkości, ale nie jest to proces ilościowy i nie jest wydajny.

Jak mogę profilować moje skrypty bash i sprawdzić, które polecenia uruchamiają się najczęściej?

Jeśli masz GNU date(lub inną wersję, która może wyświetlać nanosekundy), zrób to na początku /etc/bash.bashrc(lub gdziekolwiek chcesz rozpocząć śledzenie w dowolnym skrypcie Bash):

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

Dodaj

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

na końcu ~/.bashrc(lub na końcu sekcji dowolnego skryptu Bash, którego śledzenie chcesz zatrzymać). Plik\011Jest ósemkowa znak tabulatora.

Powinieneś uzyskać dostęp do śledzenia logowania /tmp/bashstart.PID.log który pokazuje znacznik czasu seconds.nanoseconds każdego wykonanego polecenia. Różnica między jednym momentem a drugim to ilość czasu, jaki zajął etap pośredni.

W miarę zawężania rzeczy możesz przesuwać się set -xpóźniej i set +xwcześniej (lub selektywnie nawiązywać kilka interesujących sekcji).

Chociaż nie jest tak drobnoziarnisty jak datenanosekundy GNU , Bash 5 zawiera zmienną, która podaje czas w mikrosekundach. Używanie go oszczędza ci tworzenia zewnętrznego pliku wykonywalnego dla każdej linii i działa na komputerach Mac lub w innych miejscach, które nie mają GNU date- o ile oczywiście masz Bash 5. Zmień ustawienie PS4:

PS4='+ $EPOCHREALTIME\011 '

Jak wskazał @pawamoy, możesz użyć BASH_XTRACEFDdo wysłania wyniku śledzenia do oddzielnego deskryptora pliku, jeśli masz Bash 4.1 lub nowszy. Z tej odpowiedzi :

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

Spowoduje to, że dane wyjściowe śledzenia trafią do command.txtwychodzącego pliku stdouti stdoutzostaną wyprowadzone normalnie (lub osobno przekierowane).

Profilowy grzmotnąć (4 odpowiedzi)

Edycja: marzec 2016 dodaj scriptmetodę

Czytając to, a ponieważ profilowanie jest ważnym krokiem, przeprowadziłem kilka testów i badań dotyczących tego całego pytania SO i już opublikowałem odpowiedzi.

Jest odpowiedź 4+:

• Pierwsza jest oparta na pomyśle @ DennisWilliamson, ale przy znacznie mniejszym zużyciu zasobów
• Drugi był mój (wcześniej;)
• Trzeci jest oparty na odpowiedzi @fgm, ale jest dokładniejszy.

• Ostatniego użycia script, scriptreplaya plik rozrządu .

• Na koniec małe porównanie występów na koniec.

Używanie set -xi, dateale z ograniczonymi widłami

Zapoznaj się z pomysłem @ DennisWilliamson, ale z następującą składnią będzie tylko jedno początkowe rozwidlenie do 3 poleceń:

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

Robi to datetylko raz. Istnieje szybkie demo / test, aby pokazać, jak to działa:

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

Przykładowy skrypt:

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

Uruchamiając ten skrypt, tworzysz 2 pliki: /tmp/sample-XXXX.logi /tmp/sample-XXXX.tim(gdzie XXXX to identyfikator procesu uruchomionego skryptu).

Możesz je zaprezentować za pomocą paste:

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

Lub możesz nawet obliczyć czas różnic:

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

lub na dwóch kolumnach:

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

Może renderować:

 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

Używanie trap debugi /proc/timer_listna najnowszych jądrach GNU / Linuksa, bez forków .

W ostatnich jądrach GNU / Linuksa możesz znaleźć /procplik o nazwie timer_list:

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

Gdzie aktualny czas jest sumą 5461935212966259 + 1383718821564493249, ale w nanosekundach.

Tak więc do obliczenia upływającego czasu nie ma potrzeby znajomości przesunięcia.

Dla tego rodzaju zadań napisałem elap.bash (V2) , które są pobierane przez następującą składnię:

source elap.bash-v2

lub

. elap.bash-v2 init

(Zobacz komentarze dla pełnej składni)

Możesz więc po prostu dodać tę linię u góry swojego skryptu:

. elap.bash-v2 trap2

Mała próbka:

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

Renderuj na moim hoście:

 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

Używanie trap2zamiast trapjako argumentu do polecenia źródła:

#!/bin/bash

. elap.bash-v2 trap2
...

Wyrenderuje dwie kolumny ostatnie polecenie i sumę :

 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

Za pomocą strace

Tak, stracemoże wykonać pracę:

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

Ale może być wiele rzeczy!

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

Korzystanie z bardziej ograniczonego polecenia:

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

Zrzuci lżejsze kłody:

  4519  36695 374453 sample-script-strace.log

W zależności od tego, czego szukasz, możesz być bardziej restrykcyjny:

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

Czytanie ich będzie trochę trudniejsze:

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

Oryginalny skrypt bash nie jest łatwy do naśladowania w tym ...

Korzystanie script, scriptreplayi rozrządu plik

Jako część BSD Utils , script(i scriptreplay) jest bardzo starym narzędziem, które może być używane do profilowania bash, zajmując bardzo mało miejsca.

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

Będzie produkować:

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

i wygeneruj dwa pliki:

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

Plik script.logzawiera wszystkie ślady i script.timjest plikiem czasu :

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

Możesz zobaczyć całkowity czas wykonania z pierwszą i ostatnią linią pliku dziennika i / lub podsumowując czasy w pliku czasu:

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

W pliku taktowania drugą wartością jest liczba kolejnych bajtów w odpowiednim pliku dziennika. Pozwala to na ponowne odtwarzanie pliku dziennika opcjonalnie ze współczynnikiem przyspieszenia :

scriptreplay script.{tim,log}

lub

scriptreplay script.{tim,log} 5

lub

 scriptreplay script.{tim,log} .2

Wyświetlanie czasów i poleceń obok siebie jest również nieco bardziej złożone:

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

Testy i wnioski

Aby wykonać testy, pobrałem drugą próbkę ze złożonego bash hello world , wykonanie tego skryptu na moim hoście zajmuje około 0,72 sekundy.

Na górze skryptu dodałem jeden z:

• według elap.bashfunkcji

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

• przez set -xiPS4

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

• przez set -xi początkowe rozwidlenie do długiego polecenia 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

• przez script(i set +x)

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

Czasy

I porównaj czasy wykonania (na moim hoście):

• Bezpośredni 0,72 sek
• elap.bash 13,18 sek
• set + date @ PS4 54,61 sek
• zestaw + 1 widelec 1,45 sek
• skrypt i plik czasu 2,19 sek
• strace 4,47 sek

Wyjścia

• według elap.bashfunkcji

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

• przez set -xiPS4

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

• przez set -xi początkowe rozwidlenie do długiego polecenia exec (i mój drugi pasteprzykładowy skrypt)

   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=

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

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

Wniosek

Dobrze! Jeśli moje czyste uderzenie jest szybsze niż dotychczasowe rozwidlanie każdego polecenia , moje czyste uderzenie oznacza pewne operacje na każdym poleceniu.

Sposób wyznaczenia niezależnego procesu logowania i przechowywania jest zdecydowanie bardziej wydajny.

strace to ciekawy sposób, bardziej szczegółowy, ale trudny do odczytania.

script, z scriptreplaywspółczynnikiem przyspieszenia też jest bardzo ładny, nie ma takiej samej precyzji, jak ta oparta na wymianie konsoli zamiast wykonywania procesu, ale jest bardzo lekki i wydajny (nie ten sam cel, nie to samo użycie).

Na koniec myślę, że bardziej wydajna, pod względem czytelności i wydajności jest set + 1 forkpierwsza z tej odpowiedzi, ale w porządku, w zależności od konkretnego przypadku, używam czasami stracei / lub scriptteż.

Często pomaga prześledzić wywołania systemowe

strace -c -f ./script.sh

Z instrukcji:

-c Zliczaj czas, wywołania i błędy dla każdego wywołania systemowego i raportuj podsumowanie zakończenia programu.

-f Śledź procesy potomne ...

Nie jest to dokładnie to, czego chcesz i co pokazałby Ci profiler zorientowany liniowo, ale zwykle pomaga znaleźć gorące punkty.

Możesz rzucić okiem na trappolecenie z warunkiem DEBUG . Istnieje sposób ustawienia poleceń, które mają być wykonywane wraz z poleceniami. Zobacz uwagi do odpowiedzi.

Time, xtrace, bash -x set -xi set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html ) pozostają ortodoksyjnym sposobem debugowania skryptu.

Bez względu na to, aby poszerzyć nasz horyzont, możliwe jest sprawdzenie jakiegoś systemu debugowania i profilowania dostępnego dla zwykłych programów linuksowych [tutaj jedna z list] , np. Powinien dać użyteczny oparty na valgrind szczególnie do debugowania pamięci lub sysprof do profilu cały system:

Dla sysprof:

Dzięki sysprof możesz profilować wszystkie aplikacje uruchomione na komputerze, w tym aplikacje wielowątkowe lub wieloprocesorowe ...

A następnie wybierz gałąź podprocesów, które uważasz za interesujące.

Dla Valgrind:
Z jakiegoś bardziej siłowni, wydaje się, że to możliwe, aby widoczny do Valgrind niektóre programy, które zazwyczaj możemy zainstalować z pliku binarnego (np OpenOffice ).

Można przeczytać z często zadawanych pytań valgrind, który Valgrindbędzie profilował procesy potomne, jeśli zostanie wyraźnie o to poproszony.

... Nawet jeśli domyślnie profiluje tylko proces najwyższego poziomu, więc jeśli twój program jest uruchamiany przez skrypt powłoki, skrypt Perla lub coś podobnego, Valgrind prześledzi powłokę, interpreter Perla lub równoważny. ..

Zrobi to z włączoną tą opcją

 --trace-children=yes 

Dodatkowe odniesienia:

• Podręcznik Valgrind .
• Kilka wiadomości na temat interfejsów KCachegrind i Callgrind lub także tutaj , nadal w użyciu, jak donosi wiki CERN
• Podręcznik gdb . dla gdb, które mogą być przydatne dla profilu c, program c ++ wywoływany przez skrypt.

Ten post przez Alan Hargreaves opisuje metody profilowania Bourne skrypt przy użyciu dostawcy DTrace. O ile wiem, działa to z Solarisem i OpenSolarisem (patrz: / bin / sh DTrace Provider ).

Biorąc więc pod uwagę następujący skrypt dtrace ( sh_flowtime.dw GH na podstawie oryginału ):

#!/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));
}

możesz śledzić przepływ funkcji, w tym czasy delta.

Przykładowe dane wyjściowe:

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

Następnie za pomocą sort -nrk7polecenia możesz posortować dane wyjściowe, aby pokazać najbardziej pochłaniające wywołania.

Nie znam żadnych sond dostawców dostępnych dla innych powłok, więc zrób trochę badań (wyszukiwanie na GitHub?) Lub jeśli chcesz zainwestować trochę czasu, możesz napisać takie na podstawie istniejącego przykładu sh : (patrz: Jak aktywować sh Dostawca DTrace? ).