Una gentile introduzione a Strace

La prima volta che sono venuto a conoscenza di strace è stato probabilmente leggendo questo post di Julia Evans¹: You can be a kernel hacker too. Strace è un tool presente su sistemi *nix che permette di tracciare le chiamate di sistema (systemcall) effettuate da un nostro processo.

Vediamo ora una serie di esempi per capire alcuni casi d’uso in cui strace può tornarci molto utile:

Ma si è bloccato o…

…che diavolo starà facendo questo processo? Questa è una delle domande che vi sarete sicuramente posti in più occasioni e per vari motivi. Se siete su un sistema Linux, Strace è il tool che fa per voi: è un programma pensato per il debug che cattura e visualizza tutte le chiamate di sistema fatte. Registrerà anche le comunicazione inter-processi effettuate tramite segnali.

Inoltre ci permette di estrarre informazioni utili senza neanche entrare nel codice sorgente di un programma. Ad esempio: Dove scriverà il file di log questo processo?

Per questo esempio, ho scritto un semplice programma in c che apre e chiude un file in /var/log/, e stampa un messaggio. Proviamo ad eseguirlo:

./a.out
Hello, world!

Come facciamo a capire qual è la path del file che apre, avendo solo il binario? Iniziamo lanciando strace di base e vediamo che succede:

$ strace ./a.out
execve("./a.out", ["./a.out"], [/* 17 vars */]) = 0
brk(0) = 0x1209000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f66fa09c000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=156827, ...}) = 0
mmap(NULL, 156827, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f66fa075000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P \2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1840928, ...}) = 0
mmap(NULL, 3949248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f66f9ab7000
mprotect(0x7f66f9c71000, 2097152, PROT_NONE) = 0
mmap(0x7f66f9e71000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ba000) = 0x7f66f9e71000
mmap(0x7f66f9e77000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f66f9e77000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f66fa074000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f66fa072000
arch_prctl(ARCH_SET_FS, 0x7f66fa072740) = 0
mprotect(0x7f66f9e71000, 16384, PROT_READ) = 0
mprotect(0x600000, 4096, PROT_READ) = 0
mprotect(0x7f66fa09e000, 4096, PROT_READ) = 0
munmap(0x7f66fa075000, 156827) = 0
open("/var/log/provaaa", O_WRONLY|O_CREAT|O_APPEND, 03777722151316450) = 3
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f66fa09b000
close(3) = 0
write(1, "Hello, world!", 13Hello, world!) = 13
exit_group(0) = ?
+++ exited with 0 +++

Come potete notare, ci sono più syscall di quelle che ci potremmo aspettare per un programma così semplice. Per programmi più complessi, probabilmente avremmo una lista anche più corposa. Torniamo all’obiettivo però: vogliamo capire dove si trova il file di log.

Rimuoviamo un po’ di rumore: sapendo che stiamo cercando l’apertura di un file, ci basterà usare l’opzione -e open per tracciare la systemcall open:

$ strace -e open ./a.out

sudo strace -e open ./a.out
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/var/log/provaaa", O_WRONLY|O_CREAT|O_APPEND, 03777607420342250) = 3
Hello, world!+++ exited with 0 +++

Ora è parecchio più facile capire qual è il file.

Il numero alla fine della riga indica il valore di ritorno della syscall. In generale, una syscall ritorna -1 in caso di errore (o insuccesso).

Notiamo inoltre che nell’ultima riga, viene stampato anche “Hello, world!” in mezzo alle varie syscall. Questo è effettivamente l’output del nostro programma (se guardiamo nell’output precedente troveremo la stringa proprio nel mezzo della chiamata a write).

Possiamo fare in modo di filtrare l’output del programma con quello di strace: quello di quest’ultimo viene stampato in stderr(uno dei 3 file descriptors disponibili di default in ogni programma). Per filtrare quindi, potremmo reindirizzare l’stdout per rimuovere l’output del programma.

strace ./a.out > /dev/null

A volte però, il nostro programma stampa anche degli output in stderr, che in questo modo non verranno reindirizzati. Per ovviare a questo problema, possiamo utilizzare l’opzione -o di strace per reindirizzare l’output di strace in un file dato come argomento:

$ strace -o str.out ./a.out #Eseguo il programma, e reindirizzo l'output ad str.out
Hello, World!
$ cat str.out
[output di strace]

Salire sul treno in corsa

A volte, vorremmo ispezionare l’esecuzione di un programma senza però avere la possibilità di avviarlo una seconda volta per appunto associargli strace.

Ad esempio, stiamo installando un programma che richiede parecchio tempo e ad un certo punto vorremmo sapere se l’installer si è bloccato o sta effettivamente facendo qualcosa in background.

Ecco che strace ci viene in aiuto, al costo di poter arrivare a rallentare un programma 100x, usando l’opzione -p:

$ strace -p 25045
Process 25045 attached
restart_syscall(<... resuming interrupted call ...>

L’opzione richiede un process id (PID). Per trovarlo possiamo utilizzare, ad esempio, pgrep nomeprocesso. In questo caso, ho aggiunto al programma di prima una chiamata alla funzione sleep(n) che interrompe l’esecuzione per n secondi.

Da qui, possiamo capire che il nostro programma è bloccato. In caso contrario, probabilmente, vedremmo comparire a schermo moltissime scritte appartenenti appunto a chiamate di sistema. È fortemente sconsigliato l’uso di questa opzione su software in produzione.

Programmi multiprocesso

È possibile chiedere a strace di seguire anche i fork del processo iniziale, usando l’opzione –f. In questo modo è possibile anche debuggare un programma che esegue più operazioni in parallelo. Possiamo distinguere le varie syscall stampate in output tramite il PID posto all’inizio della riga.

Vediamo un semplice utilizzo:

$ strace -f -e write ./a.out > /dev/null
Process 7460 attached
[pid 7459] write(1, "Hello, world!Ciao mondo", 23) = 23
[pid 7460] write(1, "Hello, world!", 13 <unfinished ...>
[pid 7459] +++ exited with 0 +++
<... write resumed> ) = 13
+++ exited with 0 +++

Aggiungere un timestamp

Potrebbe essere utile durante il debugging, l’opzione di aggiunta di un timestamp fornita da strace nel caso di aggiunta del parametro -t. È possibile avere più formati di timestamp:

• t per i secondi,
• tt per i microsecondi

$ strace -t -e write ls > /dev/null
16:10:16 write(1, "file.txt\n", 9) = 9
16:10:16 +++ exited with 0 +++

$ strace -tt -e write ls > /dev/null
16:16:27.791521 write(1, "file.txt\n", 9) = 9
16:16:27.792302 +++ exited with 0 +++

Benchmarking dei programmi

È anche possibile utilizzare strace per effettuare il benchamark di un programma. Esistono due parametri molto utili per questo scopo:

• -T: per il tempo speso nella funzione,
• -c: per avere un sommario delle system calls e numero di errori generati per ogni systemcall

Vediamo un esempio sul programma ls:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
 22.53 0.000171 7 23 mmap
 16.34 0.000124 9 14 mprotect
 12.65 0.000096 11 9 open
 8.30 0.000063 8 8 read
 7.51 0.000057 19 3 munmap
 6.46 0.000049 6 8 8 access
 5.40 0.000041 3 12 close
 4.74 0.000036 4 10 fstat
 3.56 0.000027 14 2 2 statfs
 3.43 0.000026 9 3 brk
 2.90 0.000022 22 1 execve
 2.90 0.000022 11 2 getdents
 1.19 0.000009 3 3 3 ioctl
 1.19 0.000009 9 1 openat
 0.53 0.000004 4 1 write
 0.40 0.000003 3 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.000759 101 13 total

Un’idea quindi potrebbe essere:

1. Avviare il programma usando l’opzione -c
2. Filtrare le systemcall in base a quella più usata, e usare il parametro -T per avere un sommario del tempo speso in ogni chiamata
3. Cercare di ottimizzare la specifica chiamata.

O ancora, cercare di capire in quale funzione si trova la syscall pesante, e cercare di limitare il numero di chiamate verso questa funzione.

Per concludere

Strace è sicuramente un tool di debugging utilissimo, anche se non siete degli sviluppatori in alcuni casi può semplificarci di molto la vita. Se avete voglia, vi consiglio di leggere questa divertente e interessante enzine proprio su strace.

[1] Lei è fantastica, se non la conoscete vi consiglio di seguirla.