Présentation de strace — un outil de traçage d'appels système et de création de rapports de signaux

Il est toujours amusant de savoir comment les choses fonctionnent réellement. Tous les programmeurs de langage C savent que, pendant le cycle entrée-traitement-sortie (input-process-output) de leur code C, un certain nombre d'appels système sont invoqués. Ne serait-il pas intéressant d'« observer » réellement quels appels système sont invoqués par votre programme ? C'est le sujet de cet article. Commençons donc.

strace est un outil qui permet de tracer les appels système générés par un processus durant son exécution. Il rend également compte des signaux (ou interruptions logicielles) reçus par le processus.

Selon la page de manuel de Linux, dans le cas le plus simple, strace exécute la commande indiquée jusqu'à ce qu'il s'arrête. Il intercepte et enregistre les appels système qui sont invoqués par un processus et les signaux qui sont reçus par un processus.

On peut jeter un coup d'œil aux divers commutateurs et options en saisissant strace dans un terminal :

$ strace
usage: strace [-dffhiqrtttTvVxx] [-a column] [-e expr] ... [-o file]
              [-p pid] ... [-s strsize] [-u username] [-E var=val] ...
              [command [arg ...]]
   or: strace -c [-e expr] ... [-O overhead] [-S sortby] [-E var=val] ...
              [command [arg ...]]
-c -- count time, calls, and errors for each syscall and report summary

[[[etc.]]]

Commençons par une démonstration très simple de son fonctionnement. Examinez le code C suivant (Listing 1) :

/* Listing 1*/

#include <stdio.h>

int main()
{
return 0;
}

Supposez que le fichier objet soit temp.o. Exécutons-le avec la commande suivante :

	
$strace ./temp.o

On obtient le fichier trace suivant :

execve("./temp.o", ["./temp.o"], [/* 36 vars */]) = 0
brk(0)                                  = 0x804a000
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) = 0xb7fba000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=68539, ...}) = 0
mmap2(NULL, 68539, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fa9000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/cmov/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0`\1\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=1307104, ...}) = 0
mmap2(NULL, 1312164, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e68000
mmap2(0xb7fa3000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13b) = 0xb7fa3000
mmap2(0xb7fa6000, 9636, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7fa6000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e67000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7e676c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb7fa3000, 4096, PROT_READ)   = 0
munmap(0xb7fa9000, 68539)               = 0
exit_group(0)                           = ?
Process 8909 detached

Essayons maintenant d'établir une corrélation entre notre compréhension théorique et le fichier trace généré ici.

Comme nous le savons, lorsque l'utilisateur saisit une commande ou un fichier objet à exécuter, le shell engendre un shell « enfant » et ce dernier se charge de l'exécution, avec l'appel système execve. Ainsi, la première ligne que nous avons dans le fichier trace est la suivante :

execve("./temp.o", ["./temp.o"], [/* 36 vars */]) = 0

Celle-ci est suivie d'appels à brk(), open, access, open, close et finalement le processus est détaché du shell qui s'arrête également avec exit_group(0).

Il apparaît que le rapport affiche tous les appels système ainsi que les arguments et la valeur de retour.

Je vais à présent démontrer les capacités de strace à effectuer un rapport de signal. Examinez le code C (Listing 2) :

/*Listing 2*/

#include <stdio.h>

int main()
{
int i;

for(i=0;i>=0;i++)
        printf("infinity\n");
return 0;
}

Supposez que le fichier objet soit temp-1.o. Exécutons-le à l'aide de la commande suivante :

	
$ strace -o trace.txt ./temp-1.o

Vous constatez qu'il montre que l'appel système write() est appelé indéfiniment. À présent, arrêtez le processus en appuyant sur Ctrl+C :

[[[...]]]

write(1, "ty\ninfinity\ninfinity\ninfinity\nin"..., 1024) = 1024
write(1, "nity\ninfinity\ninfinity\ninfinity\n"..., 1024) = 1024
write(1, "finity\ninfinity\ninfinity\ninfinit"..., 1024) = 1024
write(1, "infinity\ninfinity\ninfinity\ninfin"..., 1024) = 1024
write(1, "y\ninfinity\ninfinity\ninfinity\ninf"..., 1024) = 1024
write(1, "ity\ninfinity\ninfinity\ninfinity\ni"..., 1024) = 1024
write(1, "inity\ninfinity\ninfinity\ninfinity"..., 1024) = 1024
write(1, "nfinity\ninfinity\ninfinity\ninfini"..., 1024) = 1024
write(1, "\ninfinity\ninfinity\ninfinity\ninfi"..., 1024) = 1024
write(1, "ty\ninfinity\ninfinity\ninfinity\nin"..., 1024) = 1024
write(1, "nity\ninfinity\ninfinity\ninfinity\n"..., 1024) = 1024
write(1, "finity\ninfinity\ninfinity\ninfinit"..., 1024) = 1024
write(1, "infinity\ninfinity\ninfinity\ninfin"..., 1024) = 1024
write(1, "y\ninfinity\ninfinity\ninfinity\ninf"..., 1024) = 1024

[[[etc.]]]

À présent, ouvrez le fichier trace.txt :

	
$cat trace.txt

Les deux dernières lignes seront les suivantes :

--- SIGINT (Interrupt) @ 0 (0) ---
+++ killed by SIGINT +++

Comme nous avons interrompu l'exécution du processus à l'aide de Ctrl+C, cela a provoqué la transmission du signal SIGINT au processus et, de ce fait, strace a créé un rapport.

Grâce à strace, il est aussi possible de collecter quelques statistiques de base concernant les appels système tracés. On y parvient avec l'option -c. Par exemple :

$ strace -o trace-1.txt -c ./temp-1.o # run the above object code 'temp-1.o'
$ cat trace-1.txt 

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.007518           0     46702           write
  0.00    0.000000           0         1           read
  0.00    0.000000           0         2           open
  0.00    0.000000           0         2           close
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3         3 access
  0.00    0.000000           0         1           brk
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         1           mprotect
  0.00    0.000000           0         7           mmap2
  0.00    0.000000           0         3           fstat64
  0.00    0.000000           0         1           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.007518                 46725         3 total

Entre autres, un élément d'information utile provenant de ce qui précède est que le processus consomme le temps maximal (100 %) en appelant l'appel système write() (appelé 46 702 fois).

Cet article nous a présenté une brève introduction à quelques fonctionnalités de base de strace. Cet outil est des plus utiles lorsque vous ne disposez que du binaire d'un programme truffé de bogues et sujet à des « plantages ». Grâce à cet outil, vous pouvez vous limiter à la cause la plus vraisemblable du plantage.

Associé à GNU Debugger (gdb) et ltrace, strace donne une grande puissance de débogage au programmeur Linux.

Fun with strace and the GDB Debugger