Manuel de suivi dynamique Solaris

Chapitre 33 Suivi des processus utilisateur

DTrace est un outil extrêmement puissant de compréhension du comportement des processus utilisateur. DTrace peut s'avérer précieux lors du débogage, de l'analyse des problèmes de performance ou de la simple compréhension du comportement d'une application complexe. Ce chapitre présente les fonctions de DTrace dédiées au suivi de l'activité des processus utilisateur, ainsi que des exemples illustrant leur utilisation.

Sous-routines copyin() et copyinstr()

L'interaction de DTrace avec les processus diffère légèrement de la plupart des débogueurs ou des outils d'observation classiques. La plupart de ces outils s'exécutent dans l'étendue du processus, ce qui permet aux utilisateurs de déréférencer les pointeurs pour programmer directement les variables. Plutôt que de s'exécuter dans le cadre ou au sein du processus lui-même, les sondes de DTrace s'exécutent dans le noyau de Solaris. Pour accéder aux données du processus, une sonde doit utiliser les sous-routines copyin() ou copyinstr() pour copier les données de processus utilisateur dans l'espace d'adressage du noyau.

Étudiez, par exemple, l'appel système write(2) suivant :

ssize_t write(int fd, const void *buf, size_t nbytes);

Le programme en D suivant illustre une tentative erronée d'impression du contenu d'une chaîne transmise à l'appel système write(2).

syscall::write:entry
{
	printf("%s", stringof(arg1)); /* incorrect use of arg1 */
}

Si vous essayez d'exécuter ce script, DTrace crée des messages d'erreur similaires à l'exemple suivant :


dtrace: error on enabled probe ID 1 (ID 37: syscall::write:entry): \
    invalid address (0x10038a000) in action #1

La variable arg1, contenant la valeur du paramètre buf, correspond à une adresse renvoyant à la mémoire dans le processus exécutant le système d'appel. Pour lire la chaîne à cette adresse, utilisez la sous-routine copyinstr() et enregistrez son résultat avec l'action printf() :

syscall::write:entry
{
	printf("%s", copyinstr(arg1)); /* correct use of arg1 */

La sortie de ce script présente toutes les chaînes dont la transmission à l'appel système write(2) est en cours. Il se peut, cependant, que vous constatiez occasionnellement des sorties irrégulières similaires à l'exemple suivant :


  0     37                      write:entry mada���

La sous-routine copyinstr() prend en charge un argument d'entrée correspondant à l'adresse utilisateur d'une chaîne ASCII nulle terminée. Cependant, les tampons transmis à l'appel système write(2) peuvent renvoyer à des données binaires plutôt qu'à des chaînes ASCII. Pour n'imprimer que le nombre de chaînes prévu par le programme appelant, utilisez la sous-routine copyin() dont le second argument correspond à une taille :

syscall::write:entry
{
	printf("%s", stringof(copyin(arg1, arg2)));
}

Notez l'utilisation obligatoire de l'opérateur stringof de sorte que DTrace convertisse correctement les données utilisateur récupérées à l'aide de copyin() vers une chaîne. L'utilisation de stringof ne s'impose pas si vous utilisez copyinstr() car cette fonction retourne toujours le type string.

Évitement des erreurs

Les sous-routines copyin() et copyinstr() ne peuvent pas lire les adresses utilisateur qui n'ont pas encore été touchées. Par conséquent, même une adresse valide peut provoquer une erreur si la page contenant cette adresse n'a pas déjà subi de défaillance lors de l'accès. Examinez l'exemple suivant :


# dtrace -n syscall::open:entry'{ trace(copyinstr(arg0)); }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU     ID                    FUNCTION:NAME
dtrace: error on enabled probe ID 2 (ID 50: syscall::open:entry): invalid address
(0x9af1b) in action #1 at DIF offset 52

Dans la sortie de l'exemple ci-dessus, l'application fonctionnait correctement et l'adresse dans arg0 était valide mais renvoyait à une page à laquelle le processus correspondant n'avait pas encore accédé. Pour résoudre ce problème, attendez que le noyau ou l'application utilisent les données avant de procéder au suivi. Attendez, par exemple, le retour de l'appel système pour appliquer copyinstr(), comme illustré dans l'exemple suivant :


# dtrace -n syscall::open:entry'{ self->file = arg0; }' \
-n syscall::open:return'{ trace(copyinstr(self->file)); self->file = 0; }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU     ID                    FUNCTION:NAME
  2     51                      open:return   /dev/null                        

Suppression de l'interférence de dtrace(1M)

Si vous suivez chaque appel vers l'appel système write(2), vous allez créer une cascade de sortie. Suite à chaque appel de la fonction write(), la commande dtrace(1M) appelle la fonction write() lorsqu'elle affiche la sortie. Cette boucle d'évaluation est un bon exemple de la manière dont la commande dtrace peut interférer avec les données souhaitées. Vous pouvez utiliser un simple prédicat pour empêcher le suivi des données non désirées :

syscall::write:entry
/pid != $pid/
{
	printf("%s", stringof(copyin(arg1, arg2)));
}

La variable de macro $pid développe l'identifiant de processus du processus qui a activé les sondes. La variable pid contient l'identifiant de processus du processus dont le thread est exécuté sur la CPU sur laquelle la sonde a été déclenchée. Par conséquent, le prédicat /pid != $pid/ garantit que le script n'assure le suivi d'aucun événement lié à l'exécution de ce script.

Fournisseur syscall

Le fournisseur syscall vous permet de suivre chaque entrée et retour d'appel système. Les appels système peuvent constituer un excellent point de départ à la compréhension du comportement d'un processus, notamment si le temps d'exécution ou de blocage de ce dernier dans le noyau est considérable. Vous pouvez utiliser la commande prstat(1M) pour déterminer à quelles activités ces processus consacrent du temps :


$ prstat -m -p 31337
   PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP  
 13499 user1     53  44 0.0 0.0 0.0 0.0 2.5 0.0  4K  24  9K   0 mystery/6

Cet exemple montre que le processus utilise un temps système considérable. Ce comportement peut notamment s'expliquer par le fait que ce processus exécute un grand nombre d'appels système. Vous pouvez utiliser un programme en D simple spécifié sur la ligne de commande pour déterminer les appels système les plus fréquents :


# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }'
dtrace: description 'syscall:::entry' matched 215 probes
^C

  open                                                              1
  lwp_park                                                          2
  times                                                             4
  fcntl                                                             5
  close                                                             6
  sigaction                                                         6
  read                                                             10
  ioctl                                                            14
  sigprocmask                                                     106
  write                                                          1092

Ce rapport indique les appels systèmes les plus fréquents. Dans cet exemple, il s'agit de l'appel système write(2). Vous pouvez utiliser le fournisseur syscall pour examiner plus attentivement la source de tous les appels système write() :


# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(arg2); }'
dtrace: description 'syscall::write:entry' matched 1 probe
^C

           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   1037
               2 |@                                        3        
               4 |                                         0        
               8 |                                         0        
              16 |                                         0        
              32 |@                                        3        
              64 |                                         0        
             128 |                                         0        
             256 |                                         0        
             512 |                                         0        
            1024 |@                                        5        
            2048 |                                         0        

La sortie indique que le processus exécute de nombreux appels système write() avec une quantité de données relativement faible. Ce ratio pourrait bien être à l'origine du problème de performances de ce processus particulier. Cet exemple illustre une méthodologie générale d'étude du comportement d'un appel système.

Action de la fonction ustack()

Il est souvent utile de suivre une pile de thread de processus au moment précis de l'activation d'une sonde pour examiner un problème plus en détails. L'action de la fonction ustack() suit la pile du thread utilisateur. Si, par exemple, un processus ouvrant plusieurs fichiers rencontre occasionnellement une défaillance dans l'appel système open(2), vous pouvez utiliser l'action de la fonction ustack() pour rechercher le chemin d'accès au code exécutant la fonction open() en échec :

syscall::open:entry
/pid == $1/
{
	self->path = copyinstr(arg0);
}

syscall::open:return
/self->path != NULL && arg1 == -1/
{
	printf("open for '%s' failed", self->path);
	ustack();
}

Ce script illustre également l'utilisation de la variable de macro $1 qui récupère la valeur du premier opérande spécifié sur la ligne de commande de dtrace(1M).


# dtrace -s ./badopen.d 31337
dtrace: script './badopen.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  0     40                      open:return open for '/usr/lib/foo' failed
              libc.so.1`__open+0x4
              libc.so.1`open+0x6c
              420b0
              tcsh`dosource+0xe0
              tcsh`execute+0x978
              tcsh`execute+0xba0
              tcsh`process+0x50c
              tcsh`main+0x1d54
              tcsh`_start+0xdc

L'action de la fonction ustack() enregistre les valeurs (PC) du compteur du programme pour la pile et dtrace(1M) résout ces valeurs PC pour symboliser les noms en effectuant une recherche dans les tables des symboles du processus. Si dtrace ne parvient pas à retrouver le symbole d'une valeur PC, cette dernière est imprimée sous la forme d'un entier hexadécimal.

Si un processus se termine ou est avorté avant le formatage final des données de la fonction ustack(), dtrace risque de ne pas pouvoir convertir les valeurs PC du suivi de pile en noms de symbole et devra les afficher sous forme de nombres hexadécimaux. Pour contourner cette restriction, spécifiez un processus qui vous intéresse avec l'option -dtrace -c ou p. Pour plus d'informations sur ces options (et bien d'autres), reportez-vous au Chapitre14Utilitaire dtrace(1M). En cas d'ignorance préalable de la commande ou de l'ID de processus, vous pouvez utiliser l'exemple suivant de programme en D pour contourner cette restriction :

/*
 * This example uses the open(2) system call probe, but this technique
 * is applicable to any script using the ustack() action where the stack
 * being traced is in a process that may exit soon.
 */
 syscall::open:entry
{
	ustack();
	stop_pids[pid] = 1;
}

syscall::rexit:entry
/stop_pids[pid] != 0/
{
	printf("stopping pid %d", pid);
	stop();
	stop_pids[pid] = 0;
}

Le script ci-dessus interrompt un processus juste avant qu'il ne se termine si l'action de la fonction ustack() a été appliquée à un thread dans ce processus. Grâce à cette technique, la commande dtrace peut résoudre les valeurs PC en noms symboliques. Notez que la valeur de stop_pids[pid] est réglée sur 0 après avoir servi à supprimer la variable dynamique. N'oubliez pas de configurer la réexécution des processus interrompus à l'aide de la commande prun(1). Dans le cas contraire, votre système accumulera de nombreux processus interrompus.

Tableau uregs[]

Le tableau uregs[] vous permet d'accéder aux enregistrements utilisateur individuels. Les tables suivantes répertorient les index dans le tableau uregs[] correspondant à chaque architecture système Solaris prise en charge.

Tableau 33–1 Constantes uregs[] pour SPARC

Constante 

Enregistrer 

R_G0..R_G7

Enregistrements globaux %g0..%g7

R_O0..R_O7

Enregistrements en sortie %o0..%o7

R_L0..R_L7

Enregistrements locaux %l0..%l7

R_I0..R_I7

Enregistrements en entrée %i0..%i7

R_CCR

Enregistrement du code de condition %ccr

R_PC

Compteur de programme %pc

R_NPC

Compteur de programme suivant %npc

R_Y

Multiplier/diviser l'enregistrement %y

R_ASI

Enregistrement de l'identificateur d'espace d'adressage %asi

R_FPRS

État des enregistrements en virgule flottante %fprs

Tableau 33–2 Constantes de uregs[] pour x86

Constante 

Enregistrer 

R_CS

%cs

R_GS

%gs

R_ES

%es

R_DS

%ds

R_EDI

%edi

R_ESI

%esi

R_EBP

%ebp

R_EAX

%eax

R_ESP

%esp

R_EAX

%eax

R_EBX

%ebx

R_ECX

%ecx

R_EDX

%edx

R_TRAPNO

%trapno

R_ERR

%err

R_EIP

%eip

R_CS

%cs

R_ERR

%err

R_EFL

%efl

R_UESP

%uesp

R_SS

%ss

Sur les plates-formes AMD64, le tableau uregs possède le même contenu que sur les plates-formes x86, plus les éléments supplémentaires répertoriés dans la table suivante :

Tableau 33–3 Constantes uregs[] pour amd64

Constante 

Enregistrer 

R_RSP

%rsp

R_RFL

%rfl

R_RIP

%rip

R_RAX

%rax

R_RCX

%rcx

R_RDX

%rdx

R_RBX

%rbx

R_RBP

%rbp

R_RSI

%rsi

R_RDI

%rdi

R_R8

%r8

R_R9

%r9

R_R10

%r10

R_R11

%r11

R_R12

%r12

R_R13

%r13

R_R14

%r14

R_R15

%r15

Les alias répertoriés dans la table suivante sont utilisables sur toutes les plates-formes :

Tableau 33–4 Constantes uregs[] communes

Constante 

Enregistrer 

R_PC

Enregistrement du compteur de programme 

R_SP

Enregistrement du pointeur de pile 

R_R0

Premier code de retour 

R_R1

Second code de retour 

Fournisseur pid

Le fournisseur pid vous permet de suivre toutes les instructions d'un processus. Contrairement à la plupart des autres fournisseurs, les sondes pid sont créées à la demande en fonction des descriptions de sonde figurant dans vos programmes en D. En conséquence, aucune sonde pid n'est répertoriée dans la sortie de dtrace -l tant que vous ne les activez pas vous-même.

Suivi de la limite de fonction utilisateur

Le mode de fonctionnement le plus simple du fournisseur pid est, tout comme l'espace utilisateur, analogue au fournisseur fbt. L'exemple de programme suivant suit toutes les entrées et tous les renvois de fonction effectués à partir d'une fonction simple. La variable de macro $1 (le premier opérande sur la ligne de commande) correspond à l'ID de processus du processus à suivre. La variable de macro $2 (le second opérande sur la ligne de commande) correspond au nom de la fonction à partir de laquelle les appels de fonction doivent être suivis.


Exemple 33–1 userfunc.d : suivi des entrées et renvois de la fonction utilisateur

pid$1::$2:entry
{
	self->trace = 1;
}

pid$1::$2:return
/self->trace/
{
	self->trace = 0;
}

pid$1:::entry,
pid$1:::return
/self->trace/
{
}

Saisissez l'exemple de script ci-dessus et enregistrez-le dans le fichier userfunc.d, puis appliquez-lui la commande chmod pour le rendre exécutable. Ce script engendre une sortie similaire à l'exemple suivant :


# ./userfunc.d 15032 execute
dtrace: script './userfunc.d' matched 11594 probes
  0  -> execute                               
  0    -> execute                             
  0      -> Dfix                              
  0      <- Dfix                              
  0      -> s_strsave                         
  0        -> malloc                          
  0        <- malloc                          
  0      <- s_strsave                         
  0      -> set                               
  0        -> malloc                          
  0        <- malloc                          
  0      <- set                               
  0      -> set1                              
  0        -> tglob                           
  0        <- tglob                           
  0      <- set1                              
  0      -> setq                              
  0        -> s_strcmp                        
  0        <- s_strcmp                        
...

Vous ne pouvez utiliser le fournisseur pid que sur les processus dont l'exécution est déjà en cours. Vous pouvez utiliser la variable de macro $target (reportez-vous au Chapitre15Scripts) et les options dtrace -c et -p pour créer et extraire les processus qui vous intéressent, puis les instrumenter à l'aide de DTrace. Par exemple, vous pouvez utiliser l'exemple de script en D suivant pour déterminer la répartition des appels de fonction exécutés vers libc par un processus sujet particulier :

pid$target:libc.so::entry
{
	@[probefunc] = count();
}

Pour déterminer la répartition des appels exécutés par la commande date(1), enregistrez le script dans le fichier libc.d et exécutez la commande suivante :


# dtrace -s libc.d -c date
dtrace: script 'libc.d' matched 2476 probes
Fri Jul 30 14:08:54 PDT 2004
dtrace: pid 109196 has exited

  pthread_rwlock_unlock                                             1
  _fflush_u                                                         1
  rwlock_lock                                                       1
  rw_write_held                                                     1
  strftime                                                          1
  _close                                                            1
  _read                                                             1
  __open                                                            1
  _open                                                             1
  strstr                                                            1
  load_zoneinfo                                                     1

...
  _ti_bind_guard                                                   47
  _ti_bind_clear                                                   94

Suivi des instructions arbitraires

Vous pouvez utiliser le fournisseur pid pour suivre une instruction dans une fonction utilisateur. Le fournisseur pid crée une sonde à la demande pour chaque instruction d'une fonction. Le nom de chaque sonde correspond au décalage de l'instruction correspondante dans la fonction exprimée sous la forme d'un entier hexadécimal. Par exemple, pour activer une sonde associée à l'instruction au niveau du décalage 0x1c dans la fonction foo du module bar.so dans le processus avec PID 123, vous pouvez utiliser la commande suivante :


# dtrace -n pid123:bar.so:foo:1c

Pour activer toutes les sondes de la fonction foo, y compris la sonde de chaque instruction, vous pouvez utiliser la commande :


# dtrace -n pid123:bar.so:foo:

Cette commande fait preuve d'une technique extrêmement puissante de débogage et d'analyse des applications utilisateur. Il peut s'avérer difficile de déboguer les erreurs peu fréquentes car elles peuvent être difficiles à reproduire. En règle générale, vous pouvez identifier un problème après l'apparition de la défaillance, soit trop tard pour reconstruire le chemin d'accès au code. L'exemple suivant montre la méthode de combinaison du fournisseur pid avec le suivi spéculatif (reportez-vous au Chapitre13Suivi spéculatif) pour résoudre ce problème en suivant chaque instruction d'une fonction.


Exemple 33–2 errorpath.d : suivi du chemin d'accès au code d'une fonction utilisateur

pid$1::$2:entry
{
	self->spec = speculation();
	speculate(self->spec);
	printf("%x %x %x %x %x", arg0, arg1, arg2, arg3, arg4);
}

pid$1::$2:
/self->spec/
{
	speculate(self->spec);
}

pid$1::$2:return
/self->spec && arg1 == 0/
{
	discard(self->spec);
	self->spec = 0;
}

pid$1::$2:return
/self->spec && arg1 != 0/
{
	commit(self->spec);
	self->spec = 0;
}

L'exécution de errorpath.d produit une sortie similaire à l'exemple suivant :


# ./errorpath.d 100461 _chdir
dtrace: script './errorpath.d' matched 19 probes
CPU     ID                    FUNCTION:NAME
  0  25253                     _chdir:entry 81e08 6d140 ffbfcb20 656c73 0
  0  25253                     _chdir:entry
  0  25269                         _chdir:0
  0  25270                         _chdir:4
  0  25271                         _chdir:8
  0  25272                         _chdir:c
  0  25273                        _chdir:10
  0  25274                        _chdir:14
  0  25275                        _chdir:18
  0  25276                        _chdir:1c
  0  25277                        _chdir:20
  0  25278                        _chdir:24
  0  25279                        _chdir:28
  0  25280                        _chdir:2c
  0  25268                    _chdir:return