← Fundamentos de Sistemas Operativos Bloque 3 · El kernel y las llamadas al sistema · Tema 16 de 34

Tema 16

Observar las llamadas al sistema con strace

Venimos usando strace desde el primer tema, siempre con una línea resaltada y el resto oculto. Ahora la estudiamos como herramienta: cómo consigue ver lo que ve, cómo se lee una traza completa y cómo se la usa para averiguar por qué un programa falla, se detiene o tarda.

1. Una ventana a la frontera

Todo este bloque giró alrededor de una frontera: la que separa el espacio de usuario del kernel. Vimos que un programa solo puede atravesarla mediante llamadas al sistema, y que todo lo que hace más allá de calcular con su propia memoria —leer, escribir, crear procesos, usar la red— pasa por ellas.

De ahí se sigue algo muy útil. Si pudiéramos apostarnos en esa frontera y anotar cada cruce, sabríamos todo lo que un programa hace con el mundo exterior, sin necesidad de leer su código y sin importar en qué lenguaje esté escrito.

strace es una herramienta que ejecuta un programa y muestra, una por línea, todas las llamadas al sistema que este realiza: su nombre, sus argumentos y el valor que devuelve el kernel.

Sirve para dos cosas. La primera es aprender: muestra lo que realmente ocurre, en lugar de lo que suponemos. La segunda es diagnosticar, y es el uso que le dan a diario quienes administran sistemas: responde preguntas como qué archivo busca un programa y no encuentra, en qué está detenido o por qué tarda. La instalamos en el tema 4; si falta, está en el paquete strace de todas las distribuciones.

2. Cómo funciona: ptrace

strace no tiene privilegios especiales. Es un programa de usuario, en anillo 3, y según todo lo visto no debería poder espiar a otro proceso: cada uno tiene su memoria aislada. Lo consigue como todo lo demás: pidiéndoselo al kernel, con una llamada al sistema llamada ptrace, de process trace.

Mediante ptrace, un proceso solicita al kernel que le permita controlar a otro. A partir de ese momento, cada vez que el proceso controlado entra a una llamada al sistema o sale de ella, el kernel lo detiene y avisa al controlador, que puede examinar sus registros y su memoria antes de dejarlo continuar.

Línea de tiempo de una llamada bajo strace: el programa ejecuta syscall, el kernel lo detiene y strace anota el pedido; el kernel ejecuta la llamada, vuelve a detenerlo y strace anota el resultado; por último el programa continúa PROGRAMA OBSERVADO KERNEL STRACE syscall entra anota el pedido sys_write anota el resultado sigue
Una sola llamada del programa observado. Mientras strace trabaja, el programa está detenido.

En cada detención, strace lee los registros del programa. Son los del tema 13: el número de la llamada está en rax y los argumentos en rdi, rsi, rdx y los siguientes. Con una tabla propia que asocia cada número a un nombre y al tipo de sus argumentos, convierte esos valores en una línea legible. Cuando un argumento es una dirección, pide al kernel el contenido de la memoria del programa en ese lugar, y así puede mostrar el texto que se escribe y no solo un puntero.

De este mecanismo se derivan tres propiedades que conviene recordar durante todo el tema:

Los depuradores como gdb usan esta misma llamada para detener un programa en un punto elegido y examinar sus variables.

3. Anatomía de una línea

Cada línea de una traza tiene la forma de una llamada a función de C seguida de su resultado:

una línea de strace
openat(AT_FDCWD, "/etc/hostname", O_RDONLY|O_CLOEXEC) = 3
│      │                                              │
│      └─ los argumentos, decodificados               └─ lo que devolvió el kernel
└─ el nombre de la llamada

El kernel solo recibió números en registros. Todo lo demás —el nombre openat, la constante AT_FDCWD, el texto de la ruta, los nombres de las opciones— es una traducción que hace strace para que la línea se pueda leer. Las convenciones de esa traducción son pocas:

NotaciónSignificado
"equipo\n"El contenido de la memoria a la que apunta el argumento, mostrado como texto.
"\177ELF\2\1\1"...Los bytes no imprimibles se muestran con su código en octal. Los puntos suspensivos indican que strace cortó el texto; por defecto muestra 32 bytes.
O_RDONLY|O_CLOEXECUn número que combina varias opciones, descompuesto en sus nombres.
{st_mode=S_IFREG|0644, st_size=7, ...}Una estructura. Los puntos suspensivos indican campos que no se muestran.
["ls", "-l"]Un arreglo de cadenas.
0x7ffd1e4a7b20 /* 36 vars */Un puntero que strace no desarrolla, con un comentario sobre su contenido.
= 3El valor de retorno: aquí, un descriptor nuevo.
= -1 ENOENT (No such file or directory)La llamada falló. Se muestra como la vería un programa en C: −1, el nombre del código de errno y su descripción.
= ?La llamada no devolvió nada, porque el proceso dejó de existir. Aparece en exit_group.
+++ exited with 0 +++No es una llamada: informa que el proceso terminó, y con qué código.
--- SIGSEGV {…} ---Tampoco es una llamada: el proceso recibió una señal del kernel.

La traza se escribe en la salida de errores, para no mezclarse con la salida del programa. Aun así, en la terminal las dos aparecen entreveradas, y por eso en este tema usaremos casi siempre la opción -o archivo, que guarda la traza aparte.

4. Una traza completa, de principio a fin

En el tema 1 trazamos hola, el programa de un solo printf, y mostramos una línea. Estas son todas, con algunas repeticiones abreviadas. Son 35 llamadas para escribir un texto, y a esta altura del curso podemos explicar cada una.

terminal
$ strace -o traza.txt ./hola
Hola, sistema operativo
$ cat traza.txt
execve("./hola", ["./hola"], 0x7ffd1e4a7b20 /* 36 vars */) = 0
brk(NULL)                               = 0x5b3f8c0d2000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7c1e5a3f4000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=68423, ...}) = 0
mmap(NULL, 68423, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7c1e5a3e3000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0"..., 832) = 832
…
mmap(NULL, 2170256, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7c1e5a000000
mmap(0x7c1e5a028000, 1605632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7c1e5a028000
…
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x7c1e5a3e0740) = 0
set_tid_address(0x7c1e5a3e0a10)         = 9731
…
mprotect(0x7c1e5a1fe000, 16384, PROT_READ) = 0
…
munmap(0x7c1e5a3e3000, 68423)           = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
getrandom("\x4e\x1c\x9a\x03\xd7\x62\xb5\x80", 8, GRND_NONBLOCK) = 8
brk(NULL)                               = 0x5b3f8c0d2000
brk(0x5b3f8c0f3000)                     = 0x5b3f8c0f3000
write(1, "Hola, sistema operativo\n", 24) = 24
exit_group(0)                           = ?
+++ exited with 0 +++

La traza se divide en cuatro actos. Solo el último corresponde al código que escribimos:

ActoLlamadasQuién las haceQué ocurre
1. La cargaexecveEl proceso recién creado, todavía ejecutando el código de stracePide al kernel que reemplace su contenido por el del archivo ./hola. Es la carga del tema 9.
2. La bibliotecaDe brk al segundo close(3)El enlazador dinámicoConsulta un índice de bibliotecas, ld.so.cache; abre libc.so.6, lee su cabecera y la mapea en memoria por partes, cada una con sus permisos.
3. La preparaciónDe arch_prctl a munmapEl enlazador dinámico y el arranque de la bibliotecaConfigura datos propios del hilo, protege contra escritura zonas ya inicializadas y libera el índice, que ya no necesita.
4. El programaDe fstat(1 al finalmain y la biblioteca de CEl printf y la finalización.

El cuarto acto merece leerse línea por línea, porque es el tema 15 completo en seis llamadas:

Hay además una línea con error, la de access. No indica ningún problema: el enlazador dinámico comprueba si existe un archivo opcional de configuración, y lo normal es que no exista. Es una observación general e importante: en una traza sana hay errores. Los programas preguntan por cosas que pueden no estar, y un ENOENT es a menudo una respuesta esperada.

Tu traza será parecida, no idéntica

Las direcciones cambian en cada ejecución, y los detalles dependen de la versión de la biblioteca: en algunas, fstat aparece como newfstatat. La estructura en cuatro actos es siempre la misma, en cualquier programa enlazado dinámicamente. Reconocer dónde termina la preparación y dónde empieza el programa es la primera habilidad para leer trazas.

5. Filtrar: ver solo lo que interesa

Un programa real produce miles de líneas. La opción -e trace= limita la traza a las llamadas elegidas, que pueden indicarse por nombre o por familia. Las familias, que se escriben con el signo %, coinciden con las de la tabla del tema 13:

FiltroMuestraResponde a la pregunta
-e trace=openat,readSolo las llamadas nombradas.—
-e trace=%fileLas que reciben un nombre de archivo: openat, access, stat, unlink…¿Qué archivos toca?
-e trace=%descLas que operan sobre un descriptor: read, write, close…¿Qué lee y qué escribe?
-e trace=%processCreación, reemplazo y finalización de procesos.¿Qué otros programas lanza?
-e trace=%networksocket, connect, sendto, recvfrom…¿Con quién se comunica?
-e trace=%memorymmap, munmap, brk, mprotect.¿Cómo crece su memoria?
-e 'trace=!mmap,mprotect'Todas menos las nombradas.—
-ZSolo las llamadas que fallaron.¿Qué le negó el kernel?
-P /rutaSolo las que involucran ese archivo.¿Quién lo usa, y cómo?

La exclusión va entre comillas simples porque el signo ! tiene un significado propio en Bash. Dos ejemplos con el comando cat:

terminal
$ strace -e trace=%file -o traza.txt cat /etc/hostname
equipo
$ cat traza.txt
execve("/usr/bin/cat", ["cat", "/etc/hostname"], 0x7ffc8a1d2e48 /* 36 vars */) = 0
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/etc/hostname", O_RDONLY) = 3
+++ exited with 0 +++

$ strace -Z -e trace=%file cat notas.txt
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "notas.txt", O_RDONLY) = -1 ENOENT (No such file or directory)
cat: notas.txt: No such file or directory
+++ exited with 1 +++

En la primera traza se ve que cat abre cinco archivos y que solo el último es el que le pedimos; el penúltimo es la configuración regional, que la mayoría de las utilidades carga al empezar. En la segunda, el mensaje que cat muestra al usuario aparece justo debajo de la llamada que lo originó: el programa recibió ENOENT y lo tradujo con strerror, como hicimos en el tema 14.

6. Caso 1: un mensaje de error que no ayuda

cat informa bien sus errores. Muchos programas no. El siguiente simula uno de esos: necesita un archivo de configuración y, si no puede abrirlo, lo dice de la peor manera posible.

terco.c
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

int main(void)
{
    char ruta[256];
    int fd;

    snprintf(ruta, sizeof(ruta), "%s/.terco.conf", getenv("HOME"));

    fd = open(ruta, O_RDONLY);
    if (fd == -1) {
        fprintf(stderr, "Error: no se pudo iniciar\n");    /* ni qué, ni por qué */
        return 1;
    }
    close(fd);

    printf("Iniciado correctamente\n");
    return 0;
}

Supón que no tienes el código, solo el ejecutable, y que alguien te pide ayuda porque «no arranca»:

terminal
$ gcc -Wall -Wextra -g terco.c -o terco
$ ./terco
Error: no se pudo iniciar

$ strace -Z ./terco                 # ¿qué le negó el kernel?
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/ana/.terco.conf", O_RDONLY) = -1 ENOENT (No such file or directory)
Error: no se pudo iniciar
+++ exited with 1 +++

$ touch ~/.terco.conf               # crear el archivo que faltaba
$ ./terco
Iniciado correctamente

$ chmod 000 ~/.terco.conf           # ahora, quitarle todos los permisos
$ ./terco
Error: no se pudo iniciar
$ strace -Z ./terco 2>&1 | grep terco.conf
openat(AT_FDCWD, "/home/ana/.terco.conf", O_RDONLY) = -1 EACCES (Permission denied)

El programa da el mismo mensaje para dos problemas distintos, y la traza los distingue sin esfuerzo: primero el archivo no existía, después existía y no se podía leer. En ambos casos indica además la ruta exacta, que el mensaje omitía.

El método es siempre el mismo, y resuelve una proporción sorprendente de los problemas cotidianos:

  1. Ejecutar el programa con strace -Z, o con -e trace=%file si se sospecha de un archivo.
  2. Descartar los errores habituales del arranque, como el de ld.so.preload.
  3. Buscar el último error antes de que el programa escriba su mensaje o termine. La causa suele estar ahí.

7. Caso 2: un programa que no responde

Un programa lleva un rato en marcha y no hace nada visible. ¿Está trabajando, está esperando algo, se colgó? strace puede conectarse a un proceso que ya está en ejecución, con la opción -p seguida de su PID. Lo probamos con leer, del tema 14, que espera una línea del teclado. Hacen falta dos terminales:

terminal 1
$ ./leer
                                    # queda esperando; no escribimos nada todavía
terminal 2
$ pgrep leer                        # averiguar el PID
9801
$ sudo strace -p 9801
strace: Process 9801 attached
read(0, 

La traza se detiene en una línea a medio escribir: el nombre de la llamada, el primer argumento y nada más. No hay paréntesis de cierre ni resultado, porque la llamada todavía no volvió. Es la imagen exacta de un proceso bloqueado, tal como lo describimos en el tema 13: está dentro del kernel, dormido, esperando datos del descriptor 0. Al escribir hola y pulsar Enter en la primera terminal, la línea se completa y la traza continúa:

terminal 2, a continuación
read(0, "hola\n", 64)                   = 5
…
write(1, "read devolvio 5\n", 16)       = 16
write(1, "Contenido: [hola\n", 17)      = 17
write(1, "]\n", 2)                      = 2
exit_group(0)                           = ?
+++ exited with 0 +++

De paso, los tres write confirman el modo por líneas del tema 15: dos printf produjeron tres llamadas, porque el texto leído contenía un salto de línea en el medio.

Lo que se ve al conectarse a un proceso permite clasificar su situación de inmediato:

Lo que muestra strace -pDiagnósticoSiguiente paso
Una llamada sin terminar: read(5,Bloqueado: espera datos, una conexión o a otro proceso.Averiguar qué es ese descriptor, con la opción -y o en /proc/PID/fd.
Nada en absolutoEstá ejecutando su propio código, en modo usuario, sin pedir nada. Puede ser un cálculo largo o un bucle infinito.Confirmar con top que consume CPU.
Las mismas llamadas, repetidas sin pararUn bucle que reintenta algo que falla, o que consulta algo continuamente.Mirar qué devuelve cada una.

El segundo caso se reproduce con ./tiempos calcular, del tema 11: durante sus dos segundos de sumas, la traza no muestra ni una línea. Para desconectarse se pulsa Ctrl+C en la terminal de strace; el programa observado sigue ejecutándose como si nada.

Por qué hizo falta sudo

Poder observar un proceso es poder leer su memoria, contraseñas incluidas. Por eso el kernel restringe ptrace. Nunca se permite sobre procesos de otro usuario. Y en Ubuntu y Debian, además, un usuario común solo puede observar los procesos que él mismo lanza desde strace, no conectarse a uno ya iniciado. Lo controla el parámetro kernel.yama.ptrace_scope; con sudo la restricción no se aplica.

8. Seguir a los procesos hijos

Por defecto, strace observa un solo proceso. Si ese proceso crea otros, sus llamadas no aparecen. Es una causa frecuente de desconcierto al trazar una shell o un script: se ve cómo lanza comandos, pero no lo que los comandos hacen. La opción -f, de follow, extiende la observación a todos los descendientes.

En el tema 10 dijimos que, para ejecutar un comando, la shell pide al kernel que cree un proceso nuevo y ejecute en él el programa. Ahora podemos verlo. Trazamos una shell que ejecuta date y luego escribe un texto, mostrando solo las llamadas relacionadas con procesos:

terminal (salida abreviada)
$ strace -f -e trace=execve,clone,wait4,exit_group bash -c 'date > /dev/null; echo fin'
execve("/usr/bin/bash", ["bash", "-c", "date > /dev/null; echo fin"], 0x7ffe3b1c5a90 /* 36 vars */) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3c1a2b4a10) = 9903
strace: Process 9903 attached
[pid  9902] wait4(-1,  <unfinished ...>
[pid  9903] execve("/usr/bin/date", ["date"], 0x5c7e0d4f1b20 /* 36 vars */) = 0
[pid  9903] exit_group(0)               = ?
[pid  9903] +++ exited with 0 +++
<... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 9903
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9903, si_uid=1000, si_status=0, …} ---
…
fin
exit_group(0)                           = ?
+++ exited with 0 +++

Es el ciclo de vida completo de un comando, y cada línea corresponde a un paso:

  1. La shell crea un proceso. Llama a fork, que la biblioteca traduce a clone. El kernel devuelve 9903, el PID del hijo. A partir de aquí hay dos procesos, y strace antepone a cada línea el PID de quien la hizo. shell, PID 9902
  2. La shell espera. Llama a wait4 y queda bloqueada. La marca <unfinished ...> indica que la llamada empezó y no terminó, y que mientras tanto ocurren otras cosas. shell, PID 9902
  3. El hijo se convierte en date. Con execve reemplaza su contenido, una copia de la shell, por el del programa pedido. hijo, PID 9903
  4. date hace su trabajo y termina con exit_group. hijo, PID 9903
  5. La shell despierta. La marca <... wait4 resumed> retoma la llamada pendiente, que devuelve el PID del hijo terminado y su código de salida. El kernel le envía además la señal SIGCHLD, el aviso de que un hijo terminó. shell, PID 9902
  6. La shell continúa. echo es un comando interno, así que lo ejecuta ella misma sin crear ningún proceso. shell, PID 9902

Crear, reemplazar, esperar: toda ejecución de un comando en Unix es esa secuencia de tres llamadas. La estudiamos con detalle en el tema 26 y la recorremos completa en el tema 32. Con -f conviene añadir -o archivo; y con -ff -o archivo, strace guarda la traza de cada proceso en un archivo separado, con el PID como extensión.

9. Medir el tiempo

strace puede añadir a cada línea información de tiempo. Hay cuatro opciones, y responden preguntas distintas:

OpciónAñadeSirve para
-t, -ttAl principio, la hora del reloj; con -tt, hasta los microsegundos.Relacionar la traza con un registro o con otro suceso.
-rAl principio, el tiempo transcurrido desde la línea anterior.Ver dónde se producen las pausas.
-TAl final, entre < >, lo que duró la llamada.Encontrar las llamadas lentas.
-cNada: reemplaza la traza por un resumen estadístico.Tener una visión de conjunto.

Con -T sobre demora, el programa del tema 15 que dormía tres segundos, la llamada culpable salta a la vista:

terminal
$ strace -T -e trace=clock_nanosleep,write ./demora > /dev/null
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=3, tv_nsec=0}, 0x7ffc5d0e3a10) = 0 <3.000154>
write(1, "Procesando... listo\n", 20)   = 20 <0.000031>
+++ exited with 0 +++

Una llamada duró tres segundos y la otra treinta millonésimas. En un programa real, donde no se sabe de antemano qué es lo lento, esa columna señala si el tiempo se va esperando a un disco, a una conexión de red o a otro proceso.

La opción -c ya la usamos varias veces. Aplicada a hola, resume la traza de la sección 4:

terminal (extracto)
$ strace -c -S calls ./hola > /dev/null
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         8           mmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         3           fstat
  0.00    0.000000           0         3           mprotect
  0.00    0.000000           0         2           openat
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           write
…
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000           0        34         1 total
ColumnaSignificado
% timePorcentaje del tiempo de kernel que consumió ese tipo de llamada.
secondsTiempo total de CPU en modo kernel. Es el sys de time, desglosado.
usecs/callPromedio por llamada, en microsegundos.
callsCantidad de llamadas.
errorsCuántas de ellas fallaron.

El total es 34 y no 35 porque exit_group no se cuenta: nunca vuelve. La opción -S elige la columna por la que se ordena; sin ella, el orden es por tiempo. Hay que tener presente que estos tiempos son de CPU dentro del kernel: una llamada que pasa tres segundos bloqueada, como la de demora, figura aquí con un tiempo casi nulo. Para medir la espera se usa -T, o -c junto con -w.

El resumen es la herramienta indicada para la situación del tema 12: un sistema con el campo sy alto en top. Aplicado al proceso sospechoso, muestra en segundos qué llamada hace por millones.

10. Opciones para ver mejor

Unas pocas opciones más hacen la traza mucho más legible. La más útil es -y, que junto a cada descriptor muestra el archivo al que corresponde:

terminal
$ strace -y -e trace=openat,read,write,close -o traza.txt cat /etc/hostname
equipo
$ tail -8 traza.txt
openat(AT_FDCWD</home/ana>, "/etc/hostname", O_RDONLY) = 3</etc/hostname>
read(3</etc/hostname>, "equipo\n", 131072) = 7
write(1</dev/pts/0>, "equipo\n", 7)     = 7
read(3</etc/hostname>, "", 131072)      = 0
close(3</etc/hostname>)                 = 0
close(1</dev/pts/0>)                    = 0
close(2</dev/pts/0>)                    = 0
+++ exited with 0 +++

Sin -y, para saber qué es el descriptor 3 hay que buscar hacia atrás el openat que lo devolvió. Con ella, cada línea se entiende sola. Aquí se ve el programa copiar.c del tema 14 en su versión profesional: el mismo bucle, con un búfer de 128 KB, y el mismo read final que devuelve cero. Se ve también que el descriptor 1 es /dev/pts/0, el archivo de dispositivo que representa a la terminal. Y AT_FDCWD, que aparece en todos los openat, queda explicado: significa «a partir del directorio actual».

Esta tabla reúne las opciones del tema, y sirve como referencia rápida:

OpciónEfecto
-o archivoGuarda la traza en un archivo en lugar de mezclarla con la salida del programa.
-e trace=…Filtra por nombre de llamada o por familia.
-ZMuestra solo las llamadas que fallaron.
-P rutaMuestra solo las llamadas que involucran ese archivo.
-p PIDSe conecta a un proceso en ejecución.
-fSigue también a los procesos hijos. Con -ff -o, un archivo por proceso.
-yMuestra la ruta asociada a cada descriptor.
-s NMuestra hasta N bytes de cada cadena, en lugar de 32.
-vMuestra las estructuras completas, sin abreviar.
-t, -tt, -r, -TAñaden información de tiempo a cada línea.
-cReemplaza la traza por un resumen. -C muestra las dos cosas.
-kTras cada llamada, muestra desde qué funciones del programa se hizo.

Una combinación que conviene memorizar para investigar un programa desconocido es strace -f -y -o traza.txt programa: sigue a todos los procesos, identifica cada descriptor y deja el resultado en un archivo para examinarlo con grep y less.

11. El costo de observar

La sección 2 anticipaba que strace es lento. Cada llamada del programa observado implica detenerlo dos veces, dar la CPU a strace, que hace a su vez varias llamadas para leer registros y memoria, y devolvérsela. El efecto se mide con tiempos, del tema 11, que hace cinco millones de llamadas:

terminal
$ time ./tiempos pedir
real	0m1.612s
$ time strace -o /dev/null ./tiempos pedir
real	1m4.380s
$ time strace -o /dev/null ./tiempos calcular
real	0m2.110s

El programa que hace llamadas sin parar tardó cuarenta veces más bajo observación. El que solo calcula tardó lo mismo que siempre, porque strace no interviene mientras el programa no cruza al kernel. El factor exacto depende del equipo y de la versión, pero el orden de magnitud es ese: el costo es proporcional a la cantidad de llamadas.

De aquí salen tres precauciones:

Observar desde adentro

Existen herramientas más recientes que obtienen la misma información sin detener al programa. En lugar de vigilarlo desde otro proceso, instalan un pequeño programa de registro dentro del kernel, que anota cada llamada al pasar. perf trace y bpftrace trabajan así, con un costo decenas de veces menor, y son las indicadas para sistemas en producción. Requieren privilegios de administrador y un kernel reciente; strace sigue siendo la opción más simple y la que está en todas partes.

12. Lo que strace no ve

strace vigila una frontera, y solo registra lo que la cruza por la puerta de las llamadas al sistema. Saber qué queda fuera de su vista evita conclusiones equivocadas:

No aparece en la trazaPor quéCon qué se observa
El trabajo en modo usuario: cálculos, bucles, llamadas a strlen o qsort.No cruza al kernel.Un depurador, como gdb, o ltrace, que registra las llamadas a funciones de biblioteca.
Los printf cuyo texto sigue en el búfer.Todavía no hubo write.—
Las consultas resueltas en el vDSO, como la hora.Se atienden sin entrar al kernel.—
Los accesos a archivos mapeados con mmap.Después del mmap, leer el archivo es leer memoria.—
Las interrupciones y los fallos de página.Entran al kernel, pero no son llamadas al sistema./proc/interrupts, perf.
Lo que el kernel hace por dentro para atender una llamada.Ocurre del otro lado de la frontera.perf, bpftrace, dmesg.

La penúltima fila tiene importancia. En el tema 11 dijimos que el kernel se activa por tres vías: llamadas al sistema, interrupciones y excepciones. strace muestra solo la primera. De las otras dos apenas se ven las consecuencias: una señal como SIGSEGV cuando una excepción termina con el programa, o una llamada bloqueada que de pronto vuelve porque llegó la interrupción de un dispositivo.

Tiene además un límite de permisos. Un programa que cambia de usuario al ejecutarse, como sudo, pierde esa capacidad cuando se lo observa: el kernel no permite que un usuario común vigile un proceso con más privilegios que él. Por eso strace sudo comando no funciona, y se escribe al revés: sudo strace comando.

En otros sistemas operativos

La idea existe en todos. FreeBSD tiene truss y ktrace; macOS, dtruss, que requiere desactivar protecciones del sistema; Windows, la herramienta gráfica Process Monitor. Ninguna es tan directa como strace, en parte por lo que vimos en el tema 13: solo Linux trata las llamadas al sistema como una interfaz pública y estable.

13. Cierre del bloque

Con este tema termina el bloque dedicado al kernel y a las llamadas al sistema. Recorrimos el camino completo entre una línea de código y el hardware, en los dos sentidos:

TemaLa idea central
10. ComponentesUn sistema operativo es un kernel rodeado de bibliotecas, shell, utilidades y servicios.
11. El kernelEs un programa que no hace nada por iniciativa propia: responde a pedidos y a sucesos.
12. ModosEl procesador impone dos niveles de privilegio, y esa es la base de toda la protección.
13. Llamadas al sistemaLa única entrada voluntaria al kernel: un número, unos registros y una instrucción.
14. En CLos envoltorios hacen la llamada por nosotros y traducen los errores a errno.
15. La bibliotecaSobre los envoltorios hay una capa que ahorra llamadas, y un estándar que la hace portable.
16. straceTodo lo anterior se puede observar, en cualquier programa.

En todos estos temas, quien iniciaba la acción era el programa: pedía, y el kernel respondía. Pero ya encontramos varias veces situaciones en que el kernel actúa sin que nadie se lo pida: una tecla pulsada que despierta a un proceso dormido, un disco que avisa que terminó, un programa en un bucle infinito al que hay que quitarle la CPU. Esas entradas al kernel no las decide ningún programa. Las provoca el hardware, y son el contenido del bloque siguiente: las interrupciones.

14. Resumen

15. Preguntas de repaso

Intenta responder cada una antes de abrir la respuesta.

1. strace se ejecuta en modo usuario. ¿Cómo logra ver lo que hace otro proceso?

Se lo pide al kernel con la llamada al sistema ptrace. El kernel detiene al proceso observado cada vez que entra a una llamada o sale de ella, y permite a strace leer sus registros y su memoria.

2. ¿De dónde saca strace el nombre de la llamada y el texto de una cadena, si el kernel solo recibe números?

El nombre lo obtiene buscando en una tabla propia el número que encuentra en rax. El texto lo obtiene leyendo la memoria del proceso observado en la dirección que figura como argumento.

3. ¿Qué significan = ? y +++ exited with 0 +++?

= ? indica que la llamada no devolvió ningún valor; aparece en exit_group, porque el proceso deja de existir. La segunda línea no es una llamada: es el aviso de strace de que el proceso terminó con código 0.

4. En la traza de hola, ¿por qué hay un fstat(1, …) antes del write?

Es la biblioteca de C averiguando qué hay detrás del descriptor 1, para decidir el modo del búfer de stdout: por líneas si es una terminal, completo si es un archivo o una tubería.

5. Una traza muestra access("/etc/ld.so.preload", R_OK) = -1 ENOENT. ¿Hay que preocuparse?

No. El enlazador dinámico comprueba si existe un archivo opcional, y lo normal es que no exista. Es un error esperado, presente en casi todas las trazas.

6. Un programa termina con «Error fatal» y nada más. ¿Qué comando probarías primero, y qué buscarías?

strace -Z programa, para ver solo las llamadas que fallaron. Después de descartar los errores habituales del arranque, la última llamada fallida antes del mensaje suele indicar la causa: un archivo inexistente, un permiso denegado, una conexión rechazada.

7. strace -p muestra read(4, y se queda ahí. ¿Qué está pasando?

El proceso está bloqueado dentro de esa llamada, esperando datos del descriptor 4. La línea está incompleta porque la llamada aún no volvió. Conviene averiguar qué es ese descriptor, con -y o mirando /proc/PID/fd.

8. strace -p sobre un proceso que consume el 100 % de la CPU no muestra nada. ¿Por qué?

Porque el proceso está ejecutando su propio código en modo usuario, sin hacer llamadas al sistema. strace solo registra los cruces al kernel. Puede ser un cálculo largo o un bucle infinito.

9. Al trazar un script, se ven los clone pero no lo que hacen los comandos. ¿Qué falta?

La opción -f. Sin ella, strace observa solo el proceso inicial, y los comandos se ejecutan en procesos hijos.

10. ¿Qué tres llamadas forman la ejecución de un comando desde la shell, y quién hace cada una?

La shell crea un proceso con clone; el proceso hijo reemplaza su contenido por el del programa con execve; y la shell espera a que termine con wait4.

11. ¿Por qué un programa que solo calcula no se vuelve más lento bajo strace?

Porque strace solo interviene en las llamadas al sistema. Mientras el programa ejecuta sus propias instrucciones nadie lo detiene. El costo es proporcional a la cantidad de llamadas.

12. Menciona tres cosas que un programa hace y que strace no muestra.

El trabajo en modo usuario, como cálculos y funciones de biblioteca que no llaman al kernel; las consultas resueltas en el vDSO, como la hora; y los accesos a archivos ya mapeados en memoria. Tampoco muestra las interrupciones ni los fallos de página.

Para practicar

  1. Obtén la traza completa de hola con -o y marca en ella los cuatro actos de la sección 4. ¿Cuántas líneas tiene cada uno?
  2. Compila hola.c con -static y traza el resultado. ¿Qué actos desaparecen, y por qué? Compara con hola_asm del tema 13.
  3. Traza ./hola > salida.txt y compara la línea de fstat(1, …) con la de la ejecución en la terminal. ¿Qué campo cambia?
  4. Usa strace -e trace=%file para averiguar qué archivos abre date. ¿De cuál obtiene la zona horaria?
  5. Repite el caso 1 dando a HOME otro valor: HOME=/tmp strace -Z ./terco. ¿Qué ruta busca ahora?
  6. Lanza sleep 100 en una terminal y conéctate con strace -p desde otra. ¿En qué llamada está detenido? Desconéctate con Ctrl+C y comprueba con pgrep sleep que sigue en ejecución.
  7. Ejecuta strace -f -e trace=execve -o traza.txt bash -c 'ls | wc -l'. ¿Cuántos execve hay, y de qué procesos?
  8. Compara strace -c ls con strace -c ls -l en un directorio con muchos archivos. ¿Qué llamadas aumentan, y qué información obtiene ls con ellas?
  9. Traza mezcla, del tema 15, con -y, primero en la terminal y luego con | cat. ¿Cómo identifica strace el descriptor 1 en cada caso?
  10. Mide con time la ejecución de copiar_1, del tema 14, sobre un archivo de 1 MB, con y sin strace -o /dev/null. Calcula el factor de demora.