Shell bash saya membutuhkan waktu hingga 3-4 detik untuk memulai, sementara jika saya memulainya dengan --norcitu segera berjalan.

Saya mulai "membuat profil" /etc/bash.bashrcdan ~/.bashrcdengan memasukkan returnpernyataan secara manual dan mencari peningkatan kecepatan, tetapi ini bukan proses kuantitatif dan tidak efisien.

Bagaimana cara membuat profil skrip bash saya dan melihat perintah mana yang membutuhkan waktu paling lama untuk memulai?

Jika Anda memiliki GNU date(atau versi lain yang dapat mengeluarkan nanodetik), lakukan ini di awal /etc/bash.bashrc(atau di mana pun Anda ingin memulai pelacakan dalam skrip Bash mana pun):

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

Menambahkan

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

di akhir ~/.bashrc(atau di akhir bagian skrip Bash mana pun yang ingin Anda hentikan penelusurannya). Ini \011adalah karakter tab oktal.

Anda harus mendapatkan log jejak /tmp/bashstart.PID.logyang menunjukkan stempel waktu detik.nanoseconds dari setiap perintah yang dijalankan. Perbedaan dari satu waktu ke waktu berikutnya adalah jumlah waktu yang diambil langkah intervensi.

Saat Anda mempersempit semuanya, Anda dapat bergerak set -xnanti dan set +xsebelumnya (atau kurung beberapa bagian yang menarik secara selektif).

Meskipun tidak berbutir halus seperti datenanodetik GNU , Bash 5 menyertakan variabel yang memberikan waktu dalam mikrodetik. Menggunakannya menyelamatkan Anda dari pemijahan eksternal yang dapat dieksekusi untuk setiap baris dan berfungsi di Mac atau di tempat lain yang tidak memiliki GNU date- selama Anda memiliki Bash 5, tentu saja. Ubah pengaturan PS4:

PS4='+ $EPOCHREALTIME\011 '

Seperti yang ditunjukkan oleh @pawamoy, Anda dapat menggunakan BASH_XTRACEFDuntuk mengirim keluaran pelacakan ke deskriptor file terpisah jika Anda memiliki Bash 4.1 atau yang lebih baru. Dari jawaban ini :

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

Ini akan menyebabkan keluaran jejak pergi ke file command.txtpergi stdoutdan stdoutmenjadi keluaran secara normal (atau dialihkan secara terpisah).

Profiling pesta (4 jawaban)

Edit:script metode tambahkan Maret 2016

Membaca ini dan karena pembuatan profil adalah langkah penting, saya telah melakukan beberapa tes dan penelitian tentang seluruh pertanyaan SO ini dan jawaban yang sudah diposting.

Ada 4+ jawaban:

• Yang pertama didasarkan pada ide @ DennisWilliamson tetapi dengan konsumsi sumber daya yang jauh lebih sedikit
• Yang kedua adalah milik saya sendiri (sebelum ini;)
• Yang ketiga didasarkan pada jawaban @fgm, tetapi lebih akurat.

• Penggunaan terakhir script, scriptreplaydan file waktu .

• Akhirnya, sedikit perbandingan penampilan di bagian akhir.

Menggunakan set -xdan datetetapi dengan garpu terbatas

Ambil dari ide @ DennisWilliamson, tetapi dengan sintaks berikut, hanya akan ada satu percabangan awal ke 3 perintah:

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

Melakukan ini datehanya akan berjalan sekali. Ada demo / tes cepat untuk menunjukkan cara kerjanya:

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

Contoh skrip:

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

Dengan menjalankan skrip ini, Anda membuat 2 file: /tmp/sample-XXXX.logdan /tmp/sample-XXXX.tim(dengan XXXX adalah ID proses dari skrip yang sedang berjalan).

Anda dapat mempresentasikannya dengan menggunakan paste:

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

Atau Anda bahkan dapat menghitung waktu yang berbeda:

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

atau pada dua kolom:

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

Dapat membuat:

 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

Menggunakan trap debugdan /proc/timer_listpada kernel GNU / Linux terbaru , tanpa garpu .

Di bawah kernel terbaru GNU / Linux , Anda mungkin menemukan /procfile bernama timer_list:

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

Di mana waktu saat ini adalah jumlah 5461935212966259 + 1383718821564493249, tetapi dalam nanodetik.

Jadi untuk menghitung waktu yang berlalu , tidak perlu mengetahui offset.

Untuk jenis pekerjaan ini, saya menulis elap.bash (V2) , yang bersumber dari sintaks berikut:

source elap.bash-v2

atau

. elap.bash-v2 init

(Lihat komentar untuk sintaks lengkap)

Jadi Anda cukup menambahkan baris ini di atas skrip Anda:

. elap.bash-v2 trap2

Sampel kecil:

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

Lakukan render di host saya:

 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

Menggunakan trap2alih-alih trapsebagai argumen ke perintah sumber:

#!/bin/bash

. elap.bash-v2 trap2
...

Akan membuat dua kolom perintah terakhir dan total :

 0.000894541      0.000894541 Starting
 0.001306122      0.002200663 ((i=3))
 0.001929397      0.004130060 ((i--))
 0.103035812      0.107165872 sleep .1
 0.000875613      0.108041485 ((1))
 0.000813872      0.108855357 ((i--))
 0.104954517      0.213809874 sleep .1
 0.000900617      0.214710491 ((1))
 0.000842159      0.215552650 ((i--))
 0.104846890      0.320399540 sleep .1
 0.000899082      0.321298622 ((1))
 0.000811708      0.322110330 ((i--))
 0.000879455      0.322989785 elapCalc2
 0.322989785 first total
 0.000906692      0.323896477 elapShowTotal \e[1mfirst total\e[0m
 0.000820089      0.324716566 ((i=2))
 0.000773782      0.325490348 ((i--))
 0.024752613      0.350242961 tar -cf /tmp/test.tar -C / bin
 0.596199363      0.946442324 gzip /tmp/test.tar
 0.003007128      0.949449452 rm /tmp/test.tar.gz
 0.000791452      0.950240904 ((1))
 0.000779371      0.951020275 ((i--))
 0.030519702      0.981539977 tar -cf /tmp/test.tar -C / bin
 0.584155405      1.565695382 gzip /tmp/test.tar
 0.003058674      1.568754056 rm /tmp/test.tar.gz
 0.000955093      1.569709149 ((1))
 0.000919964      1.570629113 ((i--))
 1.571516599 total time
 0.001723708      1.572352821 EXIT

Menggunakan strace

Ya, stracebisa melakukan pekerjaan itu:

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

Tapi bisa membuat banyak barang!

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

Menggunakan perintah yang lebih terbatas:

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

Akan membuang log yang lebih ringan:

  4519  36695 374453 sample-script-strace.log

Bergantung pada apa yang Anda telusuri, Anda mungkin lebih membatasi:

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

Membacanya akan sedikit lebih sulit:

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

Skrip bash asli tidak begitu mudah diikuti dalam hal ini ...

Menggunakan script, scriptreplaydan file waktu

Sebagai bagian dari BSD Utils , script(dan scriptreplay) adalah alat yang sangat tua yang dapat digunakan untuk membuat profil bash, dengan footprint yang sangat kecil.

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

Akan menghasilkan:

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

dan menghasilkan dua file:

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

File script.logberisi semua jejak dan script.timmerupakan file waktu :

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

Anda bisa melihat total waktu eksekusi dengan baris pertama dan terakhir logfile dan / atau dengan meringkas waktu dalam file waktu:

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

Dalam file waktu, nilai kedua adalah jumlah byte berikutnya dalam file log yang sesuai. Ini memungkinkan Anda untuk memutar ulang file log secara opsional dengan faktor percepatan :

scriptreplay script.{tim,log}

atau

scriptreplay script.{tim,log} 5

atau

 scriptreplay script.{tim,log} .2

Menampilkan waktu dan perintah secara berdampingan juga sedikit lebih rumit:

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

Tes dan kesimpulan

Untuk melakukan tes, saya telah mengunduh sampel kedua di bash complex hello world , skrip ini membutuhkan waktu sekitar 0,72 detik untuk diselesaikan di host saya.

Saya telah menambahkan di atas skrip salah satu dari:

• berdasarkan elap.bashfungsi

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

• oleh set -xdanPS4

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

• oleh set -xdan garpu awal ke perintah exec panjang

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

• oleh script(dan set +x)

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

Waktu

Dan bandingkan waktu eksekusi (di host saya):

• Langsung 0,72 detik
• elap.bash 13.18 dtk
• atur + tanggal @ PS4 54,61 dtk
• setel + 1 garpu 1,45 detik
• script dan file waktu 2,19 detik
• strace 4,47 detik

Keluaran

• berdasarkan elap.bashfungsi

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

• oleh set -xdanPS4

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

• oleh set -xdan percabangan awal ke perintah exec panjang (dan pasteskrip sampel kedua saya )

   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=

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

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

Kesimpulan

Baik! Jika bash murni saya lebih cepat daripada bercabang hingga saat ini pada setiap perintah , bash murni saya menyiratkan beberapa operasi pada setiap perintah.

Cara mendedikasikan proses independen untuk logging dan penyimpanan jelas lebih efisien.

strace adalah cara yang menarik, lebih detail, tetapi sulit dibaca.

script, dengan scriptreplaydan faktor akselerasi juga sangat bagus, tidak presisi yang sama karena ini didasarkan pada pertukaran konsol daripada eksekusi proses, tetapi sangat ringan dan efisien (bukan tujuan yang sama, penggunaan yang tidak sama).

Akhirnya, saya pikir yang lebih efisien, dalam keterbacaan dan kinerja adalah set + 1 fork, Yang pertama dari jawaban ini, tetapi baik-baik saja, tergantung pada kasus tertentu, saya menggunakan kadang strace- kadang dan / atau scriptjuga.

Seringkali membantu untuk melacak panggilan sistem

strace -c -f ./script.sh

Dari manual:

-c Hitung waktu, panggilan, dan kesalahan untuk setiap panggilan sistem dan laporkan ringkasan keluar dari program.

-f Lacak proses anak ...

Ini tidak persis seperti yang Anda inginkan dan apa yang ditampilkan profiler berorientasi garis kepada Anda, tetapi biasanya membantu menemukan hot spot.

Anda mungkin melihat trapperintah dengan kondisi DEBUG . Ada cara untuk mengatur perintah yang akan dieksekusi bersama dengan perintah Anda. Lihat catatan jawabannya.

Waktu, xtrace, bash -x, set -xdan set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html ) tetap menjadi cara ortodoks untuk men-debug skrip.

Bagaimanapun juga untuk memperbesar wawasan kita, dimungkinkan untuk memberikan pemeriksaan ke beberapa sistem untuk debugging dan profiling yang tersedia untuk program Linux biasa [di sini salah satu daftarnya] , misalnya itu akan menghasilkan yang berguna berdasarkan valgrind terutama untuk men-debug memori atau sysprof ke profil seluruh sistem:

Untuk sysprof:

Dengan sysprof, Anda dapat membuat profil semua aplikasi yang berjalan di komputer Anda, termasuk aplikasi multithread atau multiprocessed ...

Dan setelah memilih cabang sub-proses yang menurut Anda menarik.

Untuk Valgrind:
Dengan beberapa gym lagi, tampaknya itu mungkin untuk membuat terlihat untuk Valgrind beberapa program yang biasa kita install dari biner (misalnya OpenOffice ).

Dimungkinkan untuk membaca dari FAQ valgrind yang Valgrindakan membuat profil proses anak jika diminta secara khusus.

... Bahkan jika secara default profil hanya melacak proses tingkat atas, dan jika program Anda dimulai dengan skrip shell , skrip Perl, atau yang serupa, Valgrind akan melacak shell, atau penerjemah Perl, atau yang setara. ..

Ini akan melakukannya dengan opsi ini diaktifkan

 --trace-children=yes 

Referensi Tambahan:

• Manual Valgrind .
• Beberapa berita tentang interface KCachegrind dan Callgrind atau juga di sini , masih digunakan seperti dilansir dari wiki CERN
• manual gdb . untuk gdb yang dapat berguna untuk profil c, program c ++ dipanggil oleh script.

Posting ini oleh Alan Hargreaves menjelaskan metode pembuatan profil skrip Bourne shell menggunakan penyedia DTrace. Sejauh yang saya tahu ini berfungsi dengan Solaris dan OpenSolaris (lihat: / bin / sh DTrace Provider ).

Jadi diberikan skrip dtrace berikut ( sh_flowtime.ddi GH berdasarkan aslinya ):

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

Anda dapat melacak aliran fungsi termasuk waktu delta.

Output sampel:

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

Kemudian menggunakan sort -nrk7perintah, Anda dapat mengurutkan output untuk menunjukkan panggilan yang paling banyak digunakan.

Saya tidak mengetahui adanya probe penyedia yang tersedia untuk shell lain, jadi lakukan beberapa penelitian (pencarian GitHub?) Atau jika Anda ingin menginvestasikan waktu, Anda dapat menulisnya berdasarkan contoh sh yang ada : (lihat: Cara mengaktifkan sh DTrace Provider? ).