¿Cómo crear un inicio lento de un script bash shell?

Mi shell bash toma hasta 3-4 segundos para iniciarse, mientras que si lo comienzo con --norc se ejecuta inmediatamente.

Empecé a ” /etc/bash.bashrc perfiles” de /etc/bash.bashrc y ~/.bashrc insertando declaraciones de return manualmente y buscando mejoras de velocidad, pero no es un proceso cuantitativo y no es eficiente.

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

Si tiene date GNU (u otra versión que puede generar nanosegundos), haga esto al comienzo de /etc/bash.bashrc (o donde quiera comenzar un rastreo en cualquier script de 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 secuencia de comandos Bash que le gustaría rastrear para detener).

Debería obtener un registro de seguimiento en /tmp/bashstart.PID.log que muestre la marca de tiempo de /tmp/bashstart.PID.log 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 mover el set -x más tarde y set +x temprano (o set +x paréntesis varias secciones de interés de forma selectiva).

Perfilado bash (4 respuestas)

Edición: marzo de 2016 add script method

Al leer esto y dado que la creación de perfiles es un paso importante, realicé algunas pruebas e investigaciones sobre toda esta pregunta de SO y las respuestas ya publicadas.

Hay más de 4 respuestas:

  • El primero se basa en la idea de @ DennisWilliamson pero con mucho menos consumo de recursos
  • El segundo era mío (antes de esto;)
  • El tercero se basa en la respuesta @fgm, pero es más preciso.
  • El último script uso, scripreplay y archivo de tiempo .

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

Usar set -x y date pero con tenedores limitados

Tome de la idea de @DennisWilliamson, pero con la siguiente syntax, 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 

Al hacerlo, se ejecutará la date solo 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 

Secuencia de comandos 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 esta secuencia de comandos, usted /tmp/sample-XXXX.log 2 archivos: /tmp/sample-XXXX.log y /tmp/sample-XXXX.tim (donde XXXX es la identificación del proceso de ejecutar la secuencia de comandos).

Puede presentarlos mediante el uso de paste :

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

O incluso puedes calcular el tiempo de diferenciación:

 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 representar:

  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 debug y /proc/timer_list en /proc/timer_list recientes de GNU / Linux, sin bifurcaciones .

Bajo los kernels recientes de GNU / Linux , puede encontrar un archivo /proc llamado timer_list :

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

Donde la hora actual es la sum de 5461935212966259 + 1383718821564493249 , pero en nanosegundos.

Por lo tanto, para calcular el tiempo transcurrido , no es necesario conocer el desplazamiento.

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

 source elap.bash-v2 

o

 . elap.bash-v2 init 

(Ver comentarios para la syntax 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 render 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 

Usar trap2 lugar de trap como argumento para el comando de origen:

 #!/bin/bash . elap.bash-v2 trap2 ... 

Presentará dos columnas ú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 

Usando strace

Sí, strace podrí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 

Vaciará 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  

El script bash original no es tan fácil de seguir en este ...

Uso de script , scriptreplay y archivo de tiempo

Como parte de BSD Utils , script (y scriptreplay ) es una herramienta muy antigua que se puede utilizar 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 genera 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.log contiene todos los rastreos y script.tim es 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 total del tiempo con la primera y la ú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 tiempo, el segundo valor es el número de los siguientes bytes en el archivo de registro correspondiente. Esto le permite la capacidad de reproducir el archivo de registro de forma opcional 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 es un poco más complejo también:

 exec 4 

Pruebas y conclusión

Para hacer pruebas, he descargado una segunda muestra en bash complex hello world , este script toma aproximadamente 0,72 segundos para completarse en mi host.

He añadido en la parte superior del guión uno de los siguientes:

  • por la función elap.bash

     #!/bin/bash source elap.bash-v2 trap2 eval "BUNCHS=(" $(perl < 
  • por set -x y PS4

     #!/bin/bash PS4='+ $(date "+%s.%N")\011 ' exec 3>&2 2>/tmp/bashstart.$$.log set -x eval "BUNCHS=(" $(perl < 
  • por set -x y fork inicial para comando long 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 < 
  • 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
  • establecer + fecha @ PS4 54.61 seg
  • establecer + 1 tenedor 1,45 segundos
  • script y archivo de tiempo 2.19 sec
  • strace 4.47 sec

Salidas

  • por la función elap.bash

      0.000950277 0.000950277 Starting 0.007618964 0.008569241 eval "BUNCHS=(" $(perl < 
  • por set -x y PS4

     ++ 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= 
  • por set -x y fork inicial a comando long exec (y mi segundo script de muestra de paste )

      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 la 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 pure bash es más rápido que bifurcar hasta la fecha en cada comando , mi pure bash implica algunas operaciones en cada comando.

La forma de dedicar un proceso independiente para registrar y almacenar es claramente más eficiente.

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

script , con scriptreplay y factor de aceleración también es muy bueno, no tiene la misma precisión ya que está basado en el intercambio de consola en lugar de en la ejecución del proceso, pero es muy ligero y eficiente (no el mismo objective, ni el mismo uso).

Finalmente, creo que cuanto más eficiente, en legibilidad y rendimiento se set + 1 fork , el primero de esta respuesta, pero en fin, dependiendo del caso específico, también uso alguna vez strace y / o screen .

A menudo ayuda a rastrear las llamadas al sistema

 strace -c -f ./script.sh 

Del manual:

-c Cuenta el tiempo, las llamadas y los errores para cada llamada al sistema e informa un resumen sobre la salida del progtwig.

-f Trace child processes …

Esto no es exactamente lo que quiere y lo que un generador de perfiles orientado a la línea le mostraría, pero generalmente ayuda a encontrar puntos críticos.

Puede echarle un vistazo al comando trap con la condición DEBUG . Hay una manera de establecer un comando (s) para ser ejecutado junto con sus comandos. Ver las notas a la respuesta.

Esta publicación de Alan Hargreaves describe el método de creación de perfiles de la secuencia de comandos de shell de Bourne con el proveedor de DTrace. Hasta donde sé, esto funciona con Solaris y OpenSolaris (ver: / bin / sh proveedor de DTrace ).

Por lo tanto, dado el siguiente script dtrace ( sh_flowtime.d en 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.

Muestra de salida:

 # ./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 comando sort -nrk7 , puede ordenar el resultado para mostrar la mayoría de las llamadas que consumen.

No estoy al tanto de ninguna sonda de proveedor disponible para otros caparazones, así que investigue (¿Búsqueda con GitHub?) O si desea invertir algo de tiempo, puede escribirlos según el ejemplo sh existente: (ver: Cómo activar sh Proveedor de DTrace? ).

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

No obstante, para ampliar nuestro horizonte, es posible verificar si hay algún sistema para la depuración y creación de perfiles disponible para los progtwigs habituales de Linux [aquí una de las listas] , por ejemplo, debería resultar útil basado en valgrind especialmente para depurar memoria o sysprof a perfil 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 luego para seleccionar la twig de subprocesos que le parezca interesante.


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

Es posible leer las preguntas frecuentes de valgrind que Valgrind perfilará los procesos hijo si se solicita explícitamente.

… Incluso si, de forma predeterminada, los perfiles solo rastrean el proceso de nivel superior, por lo que si el progtwig 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 su 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í , aún en uso, como se informa en una wiki del CERN
  • gdb manual. para gdb que puede resultar útil para el progtwig c, c ++ llamado por el script.