Jak profilować powolne uruchamianie skryptu powłoki bash?

124

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?

Andrea Spadaccini
źródło
3
Profilowałem skrypty i większość czasu spędziłem podczas konfiguracji bash_completion.
Andrea Spadaccini
1
Nie jest to zaskakujące, ponieważ jest dość duży. Możesz to przyspieszyć, usuwając części, o których wiesz, że nigdy nie będziesz potrzebować, jeśli chcesz zadać sobie trud utrzymywania zmian w aktualizacjach itp.
Wstrzymano do odwołania.
2
Można porównać: time bash -c 'exit'i time bash -i -c 'exit', a może grać z --norci --noprofile.
F. Hauri
Zobacz także tę odpowiedź (zastrzeżenie: to moje). Nie do końca o to pytasz, ale na pewno związane: unix.stackexchange.com/a/555510/384864
Johan Walles

Odpowiedzi:

128

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

Wstrzymano do odwołania.
źródło
Czy to normalne, że znak zachęty powłoki jest niewidoczny, a moje polecenia nie są odtwarzane z powrotem? Mam jednak ślad, więc mogę rozpocząć analizę… wielkie dzięki!
Andrea Spadaccini
1
@AndreaSpadaccini: Finał execpowinien przywrócić normalny stan fd2, więc powinieneś otrzymać z powrotem podpowiedź.
Wstrzymano do odwołania.
7
... właściwie, z bash 4.2 można zrobić lepiej - użycie \D{...}in PS4pozwala na rozwinięcie całkowicie dowolnego formatu czasu bez narzutu wydajności związanego z uruchamianiem datejako podprocesu.
Charles Duffy,
3
@CharlesDuffy: Oba są naprawdę fajne. Jednak GNU to daterozumie, %Na Bash 4.2 nie (ponieważ strftime(3)nie) w systemie GNU - więc arbitralnie z ograniczeniami. Twój punkt widzenia dotyczący wydajności w porównaniu z rozdzielczością jest dobry i użytkownik powinien dokonać mądrego wyboru, pamiętając, że uderzenie w wydajność jest tymczasowo włączone tylko podczas debugowania (i tylko wtedy, gdy set -xma miejsce).
Wstrzymano do odwołania.
1
W Bash 4 można również użyć zmiennej BASH_XTRACEFD do przekierowania wyjścia debugowania do innego deskryptora pliku niż domyślny (2 lub stderr). Jest to niezmiernie pomocne, gdy przychodzi czas na analizę danych wyjściowych (danych profilowania), ponieważ nie trzeba już rozplątywać wyjścia stderr i set -x (tak wiele przypadków skrajnych).
pawamoy
107

Profilowy (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ż.

F. Hauri
źródło
2
Sekcja Times jest dość pouczająca i dowodzi, że widelce nie są niczym do kichania (w rzeczywistości całkowicie dominują w wielu rodzajach skryptów). +1 za dobrą (długotrwałą) odpowiedź. Być może w przyszłości powinieneś rozważyć publikowanie oddzielnych odpowiedzi
patrz
1
Wielkie dzięki, @sehe! Znajdziesz tam pełny, gotowy do uruchomienia plik źródłowy bash: elap-bash-v3 (z pewnymi funkcjami, takimi jak zezwalanie na przezroczyste użycie STDIN i STDERR )
F. Hauri
1
W ostatnich wersjach bash (> = 4.1) można exec {BASH_XTRACEFD}>zamiast tego exec 3>&2 2>wypełnić plik dziennika tylko danymi wyjściowymi rejestrowania śledzenia, a nie innymi danymi wyjściowymi standardu standardowego.
ws_e_c421
1
Metoda exec na proces z pojedynczą datą jest bardzo sprytna i preferuję precyzję poniżej sekundy. Bo script.shmogę po prostu zrobić bash -c "exec {BASH_XTRACEFD}> >(tee trace.log | sed -u 's/^.*$//' | date -f - +%s.%N > timing.log); set -x; . script.shi uzyskać dane profilowania bez modyfikowania script.sh. Kiedy precyzja poniżej sekundy nie jest potrzebna, podoba mi się, bash -c "exec {BASH_XTRACEFD}>trace.log; set -x; PS4='+\t'; . script.shktóry czas oznacza każdą linię śledzenia z drugą dokładnością i bez rozwidlania do tej pory (niskie obciążenie).
ws_e_c421
17

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.

Fritz G. Mehner
źródło
5

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.


źródło
@Dennis Williamson: Nie używałem go od jakiegoś czasu, ale pomoc w moim systemie mówi, że „Jeśli SIGNAL_SPEC jest DEBUG, ARG jest wykonywany po każdym prostym poleceniu”.
Z Bash 4.0.33 help trap: "Jeśli SIGNAL_SPEC to DEBUG, ARG jest wykonywany przed każdym prostym poleceniem." W Bash 3.2 jest napisane „po”. To jest literówka. Od wersji Bash 2.05b działa wcześniej. Odniesienie : „Ten dokument szczegółowo opisuje zmiany między tą wersją, bash-2.05b-alpha1, a poprzednią wersją, bash-2.05a-release. ... 3. Nowe funkcje w Bash ... w. Pułapka DEBUG jest teraz uruchom przed prostymi poleceniami, ((...)) poleceniami, [[...]] warunkowymi poleceniami i pętlami for ((...)). " Testowanie w każdej wersji potwierdza, że ​​było wcześniej .
Wstrzymano do odwołania.
@Dennis Williamson: Ok, w takim razie taką mam wersję.
0

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:

Hastur
źródło
1
Nie przeciwnik, ale większość tych wskazówek, choć fajnych, nie ma tutaj znaczenia. Zadawanie odpowiedniego pytania i samodzielne odpowiadanie na nie jest bardziej mile widziane - Google „stackoverflow samo odpowiada” dla odpowiedniej etykiety.
Blaisorblade
0

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

kenorb
źródło