Debugueando a bajo nivel con strace

16 de Setiembre de 2014

En entornos Linux, más de una vez nos surge la necesidad de debuguear a bajo nivel un proceso o ejecutable para investigar las causas de su mal funcionamiento o simplemente para determinar que hace.

Para ésto podemos usar el comando strace que nos permite conocer todas las llamadas al sistema que realiza un programa.

¿Qué es una llamada al sistema?

Las llamadas al sistema son la interface entre el kernel y los programas o librerías en espacio de usuario.

Como ejemplo comunes de llamadas al sistema en Linux tenemos:

  • open – Abre archivos
  • close – Cierra archivos
  • execve – Ejecuta programas
  • etc…

Podés encontrar un listado de llamadas al sistema del kernel 2.2 acá (de un kernel viejo pero sirven como referencia)

Casi todas tienen su correspondiente man, por ejemplo haciendo man 2 open, ves más información sobre open

¿Qué cosas podemos ver con la salida de strace?

Podemos ver por ejemplo:

  • Que archivos abre o intenta abrir un proceso.
  • Cuanto demora cada llamada al sistema
  • Si existe un bucle innecesario en alguna ejecución
  • En cual llamada queda trancada la ejecución si es el caso

Ejemplos de uso

Llamadas de sistema invocadas por un comando

strace comando

Un ejemplo de esto sería:


mcanan@Acer:/tmp$ strace ls
execve("/bin/ls", ["ls"], [/* 67 vars */]) = 0
brk(0) = 0x8760000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7785000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=172115, ...}) = 0
...
...
...

Sólo un tipo de llamadas de sitema ejecutadas por un comando

strace -etipo comando

Por ejemplo si quiero ver todos los archivos que intenta abrir el comando ls:


mcanan@Acer:/tmp$ strace -eopen ls
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/i386-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/i386-linux-gnu/libacl.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/lib/i386-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 3
open("/lib/i386-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
open("/lib/i386-linux-gnu/libattr.so.1", O_RDONLY|O_CLOEXEC) = 3
...
...
...

Resumen y estadísticas de llamadas de sistema invocadas por un comando

strace -c comando

Ejemplo:


mcanan@Acer:/tmp$ strace -c ls
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.00 0.000000 0 8 read
0.00 0.000000 0 9 open
0.00 0.000000 0 12 close
0.00 0.000000 0 1 execve
0.00 0.000000 0 8 8 access
0.00 0.000000 0 3 brk
0.00 0.000000 0 2 ioctl
0.00 0.000000 0 2 munmap
0.00 0.000000 0 9 mprotect
0.00 0.000000 0 23 mmap2
0.00 0.000000 0 9 fstat64
0.00 0.000000 0 2 getdents64
0.00 0.000000 0 1 set_thread_area
0.00 0.000000 0 2 2 statfs64
0.00 0.000000 0 1 openat
------ ----------- ----------- --------- --------- ----------------
100.00 0.000000 92 10 total

Llamadas de sistema de un proceso en ejecución

strace -p PID

Con la opción -p PID se obtiene una traza de un proceso en ejecución.

Para finalizar la toma de la traza se debe presionar Ctrl + C.

Para obtener la traza del proceso y todos sus procesos hijos se debe de ejecutar con la opción -f. Ejemplo: strace -fp PID


mcanan@Acer:/tmp/1$ pgrep mysql
17973
mcanan@Acer:/tmp/1$ sudo strace -fp 17973
Process 17973 attached with 17 threads
[pid 18023] futex(0xb77e4664, FUTEX_WAIT_PRIVATE, 79, NULL 
[pid 18020] rt_sigtimedwait([HUP QUIT ALRM TERM TSTP], NULL, NULL, 8 
[pid 18011] futex(0xb7a15488, FUTEX_WAIT_PRIVATE, 1, NULL 
...
...
...

Llamadas de sistema de un proceso en ejecución imprimiendo su tiempo de ejecución

strace -T comando 

mcanan@Acer:/tmp/1$ strace -T ls
execve("/bin/ls", ["ls"], [/* 67 vars */]) = 0 
brk(0)                                  = 0x9795000 
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory) 
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77b5000 
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory) 
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 
fstat64(3, {st_mode=S_IFREG|0644, st_size=172115, ...}) = 0 
...
...
...

Más información

@mcanan