strace

Published: 24-01-2016

Updated: 09-04-2017

By: Maxime de Roucy

tags: iowait strace

J’ai eu à utiliser strace pour débugger certains problèmes. Je décrit ici quelqu’une des fonctionnalités qui m’ont été utiles. Notamment concernant le diagnostique de problèmes de performances.

Tout d’abord il faut définir quelques éléments de base :

CPU time
le temps CPU correspond au temps effectivement passé par le/les CPU à executer un programe. Par exemple, si deux programmes ayant exactement la même priorité se partage un CPU pendant 10s. Le temps d’execution de chaque programme est de 10s mais leurs temps CPU est de 5s (s’il n’y a pas d’iowait). Par contre si chaque programme « possède » son propre CPU, alors leurs temps CPU est égal à leurs temps d’execution. Les iowait ne font pas parti du temps CPU puisque le CPU ne travail pas (en tous cas sur le programme en question) durant ce lapse de temps.
user CPU time
C’est le temps CPU passé en espace utilisateur par le program. C’est à dire le temps CPU qui n’est pas consacré au appels système.
system CPU time
C’est le temps CPU passé en espace noyau. C’est à dire à exécuter les appels système.
iowait
je me contanterais de reprendre la très bonne définition donnée sur le site veithen.github.io « For a given CPU, the I/O wait time is the time during which that CPU was idle (i.e. didn’t execute any tasks) and there was at least one outstanding disk I/O operation requested by a task scheduled on that CPU (at the time it generated that I/O request) ». Il est important de comprendre que si le load du serveur est supérieur au nombre de cpu, les iowait seront toujours égale ou très proche de zero. Même si plusieurs processus attendent des informations du disque.
idle time
attention, le temps idle rapporté par les outils tel que top exclu le temps iowait bien que le CPU soit effectivement en mode idle pendant un iowait. Donc, « idle » correspond à un CPU idle sans iowait et « iowait » correspond à un CPU idle avec iowait.

Les différent pourcentage de temps CPU indiqué par top sont les suivant.

us, user    : time running un-niced user processes
sy, system  : time running kernel processes
ni, nice    : time running niced user processes
id, idle    : time spent in the kernel idle handler
wa, IO-wait : time waiting for I/O completion
hi : time spent servicing hardware interrupts
si : time spent servicing software interrupts
st : time stolen from this vm by the hypervisor

Le total doit faire 100, aucun élément n’inclu une portion de l’autre ; « 9.2 + 1.1 + 85.5 + 4 + 0.2 = 100 ».

%Cpu0  :  9,2 ut,  1,1 sy,  0,0 ni, 85,5 id,  4,0 wa,  0,0 hi,  0,2 si,  0,0 st
%Cpu1  : 16,8 ut,  1,6 sy,  0,0 ni, 79,9 id,  1,6 wa,  0,0 hi,  0,0 si,  0,0 st

Avec time :

max@laptop % cat test.cpp
#include <unistd.h>

int main (int argc, char** argv)
{
        unsigned int i = 0;
        while (i < 500000000)
        {
                ++i;
        }
        sleep(2);
}

max@laptop % g++ -O0 test.cpp

max@laptop % time ./a.out
./a.out  3,41s user 0,00s system 62% cpu 5,414 total

Ici « total » est le temps perçut par l’utilisateur c’est à dire la différence entre la date de lancement du programme et sa date de fin.

strace permet de tracer tous les appels système effectué par un programme. -c permet de compter le nombre de chaque appel système et de faire un rapport en fin d’execution. Si on utilise cette option on ne peut plus avoir le log standard de strace (le log de tous les appels à la volé). -C permet de voire les logs standard en cours d’exécution et le rapport final.

-c rapporte entre autre le temps cpu système de chaque appel. -w peut être utilisé uniquement en combinaison avec -c et permet de compabiliser le temps global de chaque appel système (y compris iowait et autre). Il fait la différence entre la date de sortie de l’appel et la date d’entré, donc tout est pris en compte.

max@laptop % strace -c ./a.out
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         4           read
  0.00    0.000000           0         5           open
  0.00    0.000000           0         5           close
  0.00    0.000000           0         5           fstat
  0.00    0.000000           0        16           mmap
  0.00    0.000000           0         8           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         1           rt_sigaction
  0.00    0.000000           0         2           rt_sigprocmask
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           nanosleep
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    54         1 total

max@laptop % strace -c -w ./a.out
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.89    2.000343     2000343         1           nanosleep
  0.03    0.000585         585         1           execve
  0.02    0.000387         194         2           rt_sigprocmask
  0.02    0.000340          21        16           mmap
  0.01    0.000200          25         8           mprotect
  0.01    0.000154         154         1           rt_sigaction
  0.01    0.000147          29         5           open
  0.00    0.000082          16         5           fstat
  0.00    0.000080          16         5           close
  0.00    0.000078          26         3           brk
  0.00    0.000072          18         4           read
  0.00    0.000036          36         1           munmap
  0.00    0.000026          26         1         1 access
  0.00    0.000016          16         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    2.002546                    54         1 total

-T permet d’ajouter à chaque entrée du log standard une indication de durée de l’appel, cette option ne peut pas être utilisé en combinaison avec -c. Comme pour -w, strace fait juste la différence entre la date de sortie de l’appel et la date d’entré, donc tout est pris en compte.

max@laptop % strace ./a.out 2>&1 | head
execve("./a.out", ["./a.out"], [/* 54 vars */]) = 0
brk(0)                                  = 0x66b000
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=191599, ...}) = 0
mmap(NULL, 191599, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f77e9024000
close(3)                                = 0
open("/usr/lib/libstdc++.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\240\237\10\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=11151952, ...}) = 0

max@laptop % strace -T -o /tmp/strace-test ./a.out

max@laptop % head /tmp/strace-test
execve("./a.out", ["./a.out"], [/* 54 vars */]) = 0 <0.000636>
brk(0)                                  = 0x10d6000 <0.000046>
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory) <0.000030>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000031>
fstat(3, {st_mode=S_IFREG|0644, st_size=191599, ...}) = 0 <0.000018>
mmap(NULL, 191599, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f096dc2b000 <0.000026>
close(3)                                = 0 <0.000017>
open("/usr/lib/libstdc++.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000032>
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\237\10\0\0\0\0\0"..., 832) = 832 <0.000021>
fstat(3, {st_mode=S_IFREG|0755, st_size=11151952, ...}) = 0 <0.000017>

max@laptop % sed -n 's/.*<\(.*\)>$/\1/p' /tmp/strace-test | paste -sd+ | bc
2.002178

-ff permet de suivre les fils du processus et créé un fichier par fils, cette option doit être utilisé accompagnée -o et n’est pas compatible avec -c. C’est beaucoup plus facile pour analyser ensuite.

-f et -ff permettent aussi de tracer tous les threads associé au processus tracé (même s’il ont été créé avant le lancement du strace). Je conseille donc de toujours utiliser strace avec l’option -ff (ou -f).

-s permet d’affiche plus (ou mois) de 32 charactères par ligne. Les noms de fichier de sont jamais tronqués. -s 0 ne permet pas d’afficher des lignes de tailles infini… mais n’affiche rien.

Par exemple pour débuger un script php qui peut s’executer sur n’importe quel processus apache. On récupère le processus apache principal (celui dont le parent est 1) et on lance :

[root@arch64-apache ~]# systemctl status httpd.service
* httpd.service - Apache Web Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled; vendor preset: disabled)
   Active: active (running) since Mon 2016-01-25 21:20:06 CET; 3min 12s ago
 Main PID: 20832 (apachectl)
   CGroup: /machine.slice/machine-arch64\x2dapache.scope/system.slice/httpd.service
           |- 2190 /usr/bin/httpd -k start -DFOREGROUND
           |-20832 /bin/sh /usr/bin/apachectl start -DFOREGROUND
           `-20869 /usr/bin/httpd -k start -DFOREGROUND

Jan 25 21:20:06 arch64-apache systemd[1]: Started Apache Web Server.
[root@arch64-apache ~]# systemctl show --property=MainPID httpd.service
MainPID=20832
[root@arch64-apache ~]# pstree -p 20832
apachectl(20832)---httpd(20869)---httpd(2190)
[root@arch64-apache ~]# strace -ff -s 512 -o /tmp/apache_strace -T -p 20869 &> /dev/null &
[1] 2268
[root@arch64-apache ~]# apachectl graceful
[root@arch64-apache ~]# kill %1
[root@arch64-apache ~]# ls /tmp/apache_strace.*
/tmp/apache_strace.20869  /tmp/apache_strace.2273

Tous les fils (ici il n’y en a qu’un) ont été re-créé et sont donc maintenant « stracé ».

List des appels système qui ont pris le plus de temps :

perl -ne '/<([^<]*)>$/ && print "$1 $_"' apache_strace.2273  | sort -k 1 -h | tail