Meu shell bash leva de 3 a 4 segundos para iniciar, enquanto se eu iniciá-lo, --norcele é executado imediatamente.

Comecei a "criar perfis" /etc/bash.bashrce ~/.bashrcinserindo returninstruções manualmente e buscando melhorias na velocidade, mas não é um processo quantitativo e não é eficiente.

Como posso criar um perfil dos meus scripts bash e ver quais comandos levam mais tempo para iniciar?

Se você possui o GNU date(ou outra versão que pode gerar nanossegundos), faça isso no início de /etc/bash.bashrc(ou onde você desejar iniciar um rastreamento em qualquer script do Bash):

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

adicionar

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

no final de ~/.bashrc(ou no final da seção de qualquer script do Bash que você deseja rastrear para parar). O \011é um caractere de tabulação octal.

Você deve obter um log de rastreamento /tmp/bashstart.PID.logque mostre o carimbo de data e hora de segundos. Nanossegundos de cada comando que foi executado. A diferença de uma vez para a outra é a quantidade de tempo que a etapa intermediária levou.

À medida que reduz as coisas, você pode se mover set -xmais tarde e mais set +xcedo (ou agrupar várias seções de interesse seletivamente).

Embora não seja tão refinado quanto dateos nanossegundos do GNU , o Bash 5 inclui uma variável que fornece o tempo em microssegundos. Seu uso evita que você crie um executável externo para todas as linhas e funcione em Macs ou em outro lugar que não possua GNU date- desde que você tenha o Bash 5, é claro. Altere a configuração de PS4:

PS4='+ $EPOCHREALTIME\011 '

Conforme apontado por @pawamoy, você pode BASH_XTRACEFDenviar a saída do rastreio para um descritor de arquivo separado, se você tiver o Bash 4.1 ou posterior. A partir desta resposta :

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

Isso fará com que a saída de rastreio vá para o arquivo command.txtsaindo stdoute saia stdoutnormalmente (ou seja redirecionada separadamente).

Criação de perfil festança (4 respostas)

Editar: março de 2016 adicionar scriptmétodo

Lendo isso e porque a criação de perfil é uma etapa importante, fiz alguns testes e pesquisas sobre toda essa questão do SO e já postei respostas.

Há 4+ respostas:

• O primeiro é baseado na ideia de @ DennisWilliamson, mas com muito menos consumo de recursos
• O segundo era meu (antes disso;)
• O terceiro é baseado na resposta @fgm, mas mais preciso.

• A última utilização script, scriptreplaye arquivo tempo .

• Finalmente, uma pequena comparação de performances no final.

Usando set -xe datecom garfos limitados

Respeite a ideia de @ DennisWilliamson, mas com a seguinte sintaxe, haverá apenas uma bifurcação inicial para 3 comandos:

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

Fazer isso será executado dateapenas uma vez. Há uma demonstração / teste rápido para mostrar como funciona:

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

Exemplo de script:

#!/bin/bash

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

for ((i=3;i--;));do sleep .1;done

for ((i=2;i--;))
do
    tar -cf /tmp/test.tar -C / bin
    gzip /tmp/test.tar
    rm /tmp/test.tar.gz
done

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

Ao executar esse script, você cria 2 arquivos: /tmp/sample-XXXX.loge /tmp/sample-XXXX.tim(onde XXXX é a identificação do processo de execução do script).

Você pode apresentá-los usando paste:

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

Ou você pode até calcular o tempo de diferença:

paste <(
    while read tim ;do
        crt=000000000$((${tim//.}-10#0$last))
        printf "%12.9f\n" ${crt:0:${#crt}-9}.${crt:${#crt}-9}
        last=${tim//.}
      done < sample-time.24804.tim
  ) sample-time.24804.log 

 1388487534.391309713        + (( i=3 ))
 0.000080807        + (( i-- ))
 0.000008312        + sleep .1
 0.101304843        + (( 1 ))
 0.000032616        + (( i-- ))
 0.000007124        + sleep .1
 0.101251684        + (( 1 ))
 0.000033036        + (( i-- ))
 0.000007054        + sleep .1
 0.104013813        + (( 1 ))
 0.000026959        + (( i-- ))
 0.000006915        + (( i=2 ))
 0.000006635        + (( i-- ))
 0.000006844        + tar -cf /tmp/test.tar -C / bin
 0.022655107        + gzip /tmp/test.tar
 0.637042668        + rm /tmp/test.tar.gz
 0.000823649        + (( 1 ))
 0.000011314        + (( i-- ))
 0.000006915        + tar -cf /tmp/test.tar -C / bin
 0.016084482        + gzip /tmp/test.tar
 0.627798263        + rm /tmp/test.tar.gz
 0.001294946        + (( 1 ))
 0.000023187        + (( i-- ))
 0.000006845        + set +x

ou em duas colunas:

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

Pode render:

 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

Usando trap debuge /proc/timer_listnos kernels recentes do GNU / Linux, sem forks .

Nos kernels recentes do GNU / Linux , você pode encontrar um /procarquivo chamado timer_list:

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

Onde o tempo atual é a soma de 5461935212966259 + 1383718821564493249, mas em nanossegundos.

Portanto, para calcular o tempo decorrido , não há necessidade de saber o deslocamento.

Para esse tipo de trabalho, escrevi elap.bash (V2) , que é originado pela seguinte sintaxe:

source elap.bash-v2

ou

. elap.bash-v2 init

(Veja os comentários para obter a sintaxe completa)

Então você pode simplesmente adicionar esta linha na parte superior do seu script:

. elap.bash-v2 trap2

Pouca amostra:

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

Renderize no meu 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

Usando em trap2vez de trapcomo argumento para o comando source:

#!/bin/bash

. elap.bash-v2 trap2
...

Renderizará o último comando e o total de duas colunas :

 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

Usando strace

Sim, stracepoderia fazer o trabalho:

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

Mas poderia fazer muitas coisas!

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

Usando um comando mais restrito:

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

Despejará um log mais leve:

  4519  36695 374453 sample-script-strace.log

Dependendo do que você está procurando, você pode ser mais restritivo:

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

Lê-los será um pouco mais difícil:

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

O script bash original não é tão fácil de seguir neste ...

Usando script, scriptreplaye cronometrando arquivo

Como parte do BSD Utils , script(e scriptreplay) é uma ferramenta muito antiga que pode ser usada para fazer o perfil do bash, com uma área muito pequena.

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

Vai produzir:

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

e gere dois arquivos:

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

O arquivo script.logcontém todos os rastreios e script.timé o arquivo de temporização :

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

Você pode ver a execução do tempo total com a primeira e a última linha do arquivo de log e / ou resumindo os tempos no arquivo de temporização:

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

No arquivo de temporização, o segundo valor é o número de próximos bytes no arquivo de log correspondente. Isso permite reproduzir o arquivo de log opcionalmente com um fator de aceleração :

scriptreplay script.{tim,log}

ou

scriptreplay script.{tim,log} 5

ou

 scriptreplay script.{tim,log} .2

Mostrar horários e comandos lado a lado também é um pouco mais complexo:

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

Testes e conclusão

Para fazer testes, baixei o segundo exemplo no bash complex hello world , esse script leva aproximadamente 0,72 s para ser concluído no meu host.

Eu adicionei no topo do script um dos seguintes:

• por elap.bashfunção

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

• por set -xePS4

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

• por set -xe bifurcação inicial ao comando exec longo

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

• por script(e set +x)

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

Vezes

E compare os tempos de execução (no meu host):

• Direto 0,72 seg
• elap.bash 13,18 sec
• jogo + data @ PS4 54.61 seg
• conjunto + 1 garfo 1,45 s
• arquivo de script e de tempo 2.19 seg
• strace 4.47 seg

Saídas

• por elap.bashfunção

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

• por set -xePS4

  ++ 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 -xe fork inicial para o comando exec longo (e meu segundo pastescript de exemplo)

   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=

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

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

Conclusão

Bem! Se meu bash puro for mais rápido do que bifurcar até o momento em cada comando , meu bash puro implica algumas operações em cada comando.

A maneira de dedicar um processo independente para registro e armazenamento é claramente mais eficiente.

strace é uma maneira interessante, mais detalhada, mas difícil de ler.

script, with scriptreplaye fator de aceleração também é muito bom, não é a mesma precisão, pois ela é baseada na troca de console em vez da execução do processo, mas muito leve e eficiente (sem o mesmo objetivo, sem o mesmo uso).

Por fim, acho que quanto mais eficiente, em legibilidade e desempenho set + 1 fork, é o primeiro desta resposta, mas, dependendo do caso específico, uso em algum momento stracee / ou scripttambém.

Muitas vezes, ajuda a rastrear as chamadas do sistema

strace -c -f ./script.sh

Do manual:

-c Conte o tempo, as chamadas e os erros de cada chamada do sistema e relate um resumo da saída do programa.

-f Rastrear processos filho ...

Não é exatamente isso que você deseja e o que um criador de perfil orientado a linhas mostraria para você, mas geralmente ajuda a encontrar pontos de acesso.

Você pode dar uma olhada no trapcomando com a condição DEBUG . Existe uma maneira de definir um comando a ser executado junto com seus comandos. Veja as notas na resposta.

Tempo, xtrace, bash -x set -xe set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html ) continuam sendo a maneira ortodoxa de depurar um script.

Não obstante, para ampliar nosso horizonte, é possível verificar alguns sistemas para depuração e criação de perfil disponíveis para os programas Linux comuns [aqui uma das listas] , por exemplo, deve resultar útil em um baseado em valgrind, especialmente para depurar memória ou sysprof para criar um perfil todo o sistema:

Para sysprof:

Com o sysprof, você pode criar um perfil de todos os aplicativos em execução na sua máquina, incluindo um aplicativo multithread ou multiprocessado ...

E depois selecione o ramo de subprocessos que você achar interessante.

Para o Valgrind:
Com um pouco mais de academia, parece possível tornar visível para o Valgrind alguns programas que geralmente instalamos a partir do binário (por exemplo, OpenOffice ).

É possível ler as perguntas frequentes do valgrind que analisarãoValgrind os processos filhos, se solicitado explicitamente.

... Mesmo que, por padrão, o perfil apenas rastreie o processo de nível superior, e se o seu programa for iniciado por um script de shell , script Perl ou algo semelhante, o Valgrind rastreará o shell ou o interpretador Perl ou equivalente. ..

Isso será feito com esta opção ativada

 --trace-children=yes 

Referências adicionais:

• Manual Valgrind .
• Algumas notícias sobre as interfaces KCachegrind e Callgrind ou também aqui , ainda em uso, conforme relatado em um wiki do CERN
• manual gdb . para gdb que pode resultar útil para criar perfil do programa c, c ++ chamado pelo script.

Esta postagem de Alan Hargreaves descreve o método de criação de perfil de script de shell Bourne usando o provedor DTrace. Tanto quanto sei, isso funciona com o Solaris e o OpenSolaris (consulte: / bin / sh DTrace Provider ).

Dado o seguinte script dtrace ( sh_flowtime.dno GH com base no 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));
}

você pode rastrear o fluxo da função, incluindo tempos delta.

Saída de amostra:

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

Em seguida, usando o sort -nrk7comando, você pode classificar a saída para mostrar as chamadas que mais consomem.

Não conheço nenhum fornecedor de probes disponível para outros shells, assim como algumas pesquisas (pesquisa no GitHub?) Ou, se você quiser investir algum tempo, pode escrevê-lo com base no exemplo sh existente : (consulte: Como ativar sh Provedor DTrace? ).