Mi shell de bash tarda entre 3 y 4 segundos en iniciarse, mientras que si lo inicio --norcse ejecuta de inmediato.

Comencé a "perfilar" /etc/bash.bashrce ~/.bashrcinsertando manualmente returndeclaraciones y buscando mejoras de velocidad, pero no es un proceso cuantitativo y no es eficiente.

¿Cómo puedo perfilar mis scripts de bash y ver qué comandos tardan más en iniciarse?

Si tiene GNU date(u otra versión que puede generar nanosegundos), haga esto al comienzo de /etc/bash.bashrc(o donde quiera que comience un rastreo en cualquier script Bash):

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

añadir

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

al final de ~/.bashrc(o al final de la sección de cualquier script de Bash que le gustaría detener el seguimiento). El \011es un carácter de tabulación octal.

Debería obtener un registro de seguimiento /tmp/bashstart.PID.logque muestre la marca de tiempo segundos.nanosegundos de cada comando que se ejecutó. La diferencia de una vez a la siguiente es la cantidad de tiempo que tomó el paso intermedio.

A medida que reduce las cosas, puede moverse set -xmás tarde y más set +xtemprano (o poner entre paréntesis varias secciones de interés selectivamente).

Aunque no es tan fino como datelos nanosegundos de GNU , Bash 5 incluye una variable que da el tiempo en microsegundos. Usarlo le evita generar un ejecutable externo para cada línea y funciona en Mac o en cualquier otro lugar que no tenga GNU date, siempre que tenga Bash 5, por supuesto. Cambiar la configuración de PS4:

PS4='+ $EPOCHREALTIME\011 '

Como señaló @pawamoy, puede usar BASH_XTRACEFDpara enviar la salida de la traza a un descriptor de archivo separado si tiene Bash 4.1 o posterior. De esta respuesta :

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

Esto hará que la salida de rastreo vaya al archivo que se command.txtva stdouty stdoutque se envíe normalmente (o se redirija por separado).

Perfilado intento (4 respuestas)

Editar: marzo de 2016 agregar scriptmétodo

Al leer esto y porque la creación de perfiles es un paso importante, he realizado algunas pruebas e investigaciones sobre toda esta pregunta SO y ya he publicado respuestas.

Hay 4+ respuestas:

• El primero se basa en la idea de @ DennisWilliamson pero con mucho menos consumo de recursos.
• El segundo era el mío (antes de esto;)
• El tercero se basa en la respuesta @fgm, pero más preciso.

• El último uso script, scriptreplayy el archivo de tiempo .

• Finalmente, una pequeña comparación de actuaciones al final.

Uso set -xy datepero con horquillas limitadas

Tome la idea de @ DennisWilliamson, pero con la siguiente sintaxis, solo habrá una bifurcación 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

Hacer esto datesolo se ejecutará una vez. Hay una demostración / prueba rápida para mostrar cómo funciona:

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

Script de muestra:

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

Al ejecutar este script, crea 2 archivos: /tmp/sample-XXXX.logy /tmp/sample-XXXX.tim(donde XXXX es la identificación del proceso del script en ejecución).

Puede presentarlos usando paste:

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

O incluso puede calcular el tiempo de diferencia:

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

o en dos columnas:

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

Puede renderizar:

 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

Utilizando trap debugy /proc/timer_listen kernels recientes de GNU / Linux, sin forks .

Bajo los núcleos recientes de GNU / Linux , puede encontrar un /procarchivo llamado timer_list:

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

Donde el tiempo actual es la suma de 5461935212966259 + 1383718821564493249, pero en nanosegundos.

Entonces, para calcular el tiempo transcurrido , no hay necesidad de conocer el desplazamiento.

Para este tipo de trabajos, escribí elap.bash (V2) , que se obtiene de la siguiente sintaxis:

source elap.bash-v2

o

. elap.bash-v2 init

(Ver comentarios para sintaxis completa)

Entonces, simplemente podría agregar esta línea en la parte superior de su script:

. elap.bash-v2 trap2

Pequeña muestra:

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

Hacer en mi 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 en trap2lugar de trapcomo argumento para el comando de origen:

#!/bin/bash

. elap.bash-v2 trap2
...

Representará dos columnas como último comando y 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

Utilizando strace

Sí, stracepodría hacer el trabajo:

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

¡Pero podría hacer muchas cosas!

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

Usando un comando más restringido:

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

Volcará el registro más ligero:

  4519  36695 374453 sample-script-strace.log

Dependiendo de lo que esté buscando, puede ser más restrictivo:

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

Leerlos será un poco más 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) ---

El guión original de bash no es tan fácil de seguir en este ...

Utilizando script, scriptreplayy el archivo de sincronización

Como parte de BSD Utils , script(y scriptreplay) es una herramienta muy antigua que se puede usar para perfilar bash, con una huella muy pequeña.

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

Producirá:

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

y generar dos archivos:

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

El archivo script.logcontiene todos los rastros y script.times el archivo de tiempo :

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

Puede ver la ejecución del tiempo total con la primera y última línea del archivo de registro y / o resumiendo los tiempos en el archivo de tiempo:

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

En el archivo de temporización, el segundo valor es el número de bytes siguientes en el archivo de registro correspondiente. Esto le permite reproducir el archivo de registro opcionalmente con un factor de aceleración :

scriptreplay script.{tim,log}

o

scriptreplay script.{tim,log} 5

o

 scriptreplay script.{tim,log} .2

Mostrar tiempos y comandos uno al lado del otro también es un poco más complejo:

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

Pruebas y conclusión

Para realizar pruebas, descargué una segunda muestra en bash complex hello world , este script tarda aproximadamente 0,72 segundos en completarse en mi host.

He agregado en la parte superior del script uno de:

• por elap.bashfunción

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

• por set -xyPS4

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

• por set -xy tenedor inicial a largo comando 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

• por script(y set +x)

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

Veces

Y compare los tiempos de ejecución (en mi host):

• Directo 0.72 seg.
• elap.bash 13.18 sec
• set + date @ PS4 54.61 sec
• set + 1 tenedor 1.45 seg
• script y archivo de sincronización 2.19 sec
• strace 4.47 sec

Salidas

• por elap.bashfunción

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

  ++ 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 -xy fork inicial al comando exec largo (y mi segundo pastescript de muestra)

   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=

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

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

Conclusión

¡Bien! Si mi bash puro es más rápido que bifurcar hasta la fecha en cada comando , mi bash puro implica algunas operaciones en cada comando.

La forma de dedicar un proceso independiente para el registro y el almacenamiento es claramente más eficiente.

strace Es una forma interesante, más detallada, pero difícil de leer.

script, con scriptreplayy el factor de aceleración también es muy bueno, no es la misma precisión ya que se basa en el intercambio de la consola en lugar de la ejecución del proceso, pero es muy ligero y eficiente (no es el mismo objetivo, no es el mismo uso).

Finalmente, creo que lo más eficiente, en cuanto a legibilidad y rendimiento es set + 1 fork, La primera de esta respuesta, pero en fin, dependiendo del caso específico, lo uso en algún momento stracey / o scripttambién.

A menudo ayuda rastrear las llamadas del sistema

strace -c -f ./script.sh

Del manual:

-c Cuente el tiempo, las llamadas y los errores para cada llamada al sistema e informe un resumen al salir del programa.

-f Rastrear procesos secundarios ...

Esto no es exactamente lo que desea y lo que le mostraría un generador de perfiles orientado a líneas, pero generalmente ayuda a encontrar puntos calientes.

Puede echar un vistazo al trapcomando con la condición DEBUG . Hay una manera de configurar un comando (s) para que se ejecute junto con sus comandos. Ver las notas a la respuesta.

Time, xtrace, bash -x set -xy set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html ) siguen siendo la forma ortodoxa de depurar un script.

Sin embargo, para ampliar nuestro horizonte, es posible realizar una verificación en algún sistema para la depuración y la creación de perfiles disponibles para los programas habituales de Linux [aquí una de las listas] , por ejemplo, debería resultar útil en función de valgrind, especialmente para depurar memoria o sysprof para perfilar todo el sistema:

Para sysprof:

Con sysprof, puede perfilar todas las aplicaciones que se ejecutan en su máquina, incluida una aplicación multiproceso o multiproceso ...

Y después de seleccionar la rama de subprocesos que le parezca interesante.

Para Valgrind:
con un poco más de gimnasio, parece que es posible hacer visibles para Valgrind algunos programas que generalmente instalamos desde binarios (por ejemplo, OpenOffice ).

Es posible leer las preguntas frecuentes de valgrind que Valgrindperfilarán los procesos secundarios si se solicita explícitamente.

... Incluso si de forma predeterminada, los perfiles solo rastrean el proceso de nivel superior, por lo que si su programa se inicia con un script de shell , un script de Perl o algo similar, Valgrind rastreará el shell, o el intérprete de Perl, o equivalente. ..

Lo hará con esta opción habilitada

 --trace-children=yes 

Referencias adicionales

• Valgrind manual.
• Algunas noticias sobre las interfaces KCachegrind y Callgrind o también aquí , todavía en uso según lo informado por un wiki de CERN
• manual de gdb . para gdb que puede resultar útil para el perfil c, programa c ++ llamado por el script.

Esta publicación de Alan Hargreaves describe el método para perfilar el script de shell Bourne utilizando el proveedor DTrace. Hasta donde yo sé, esto funciona con Solaris y OpenSolaris (ver: / bin / sh DTrace Provider ).

Entonces, dado el siguiente script dtrace ( sh_flowtime.den GH basado en el 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));
}

puede rastrear el flujo de la función, incluidos los tiempos delta.

Salida de muestra:

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

Luego, utilizando el sort -nrk7comando, puede ordenar la salida para mostrar las llamadas más consumidoras.

No conozco ningún proveedor de sondas disponibles para otros shells, así que investigue un poco (¿busca en GitHub?) O si desea invertir algo de tiempo, puede escribirlo según el ejemplo sh existente : (ver: Cómo activar sh Proveedor de DTrace? ).