Capítulo 33 Seguimiento de procesos de usuario

DTrace es una herramienta extremedamente potente para comprender el comportamiento de los procesos de usuario. DTrace desempeña un papel excepcional a la hora de depurar o analizar problemas de rendimiento o simplemente para conocer el comportamiento de una aplicación compleja. Este capítulo se centra en las utilidades de DTrace relevantes para el seguimiento de la actividad de los procesos de usuario y proporciona ejemplos que ilustran su uso.

Subrutinas copyin() y copyinstr()

La interacción de DTrace con los procesos varía un poco con respecto a los depuradores más tradicionales o las herramientas de observabilidad. Muchas de estas herramientas parece que se ejecutan dentro del ámbito de los procesos, permitiendo que los usuarios establezcan que los punteros dejen de hacer referencia directa a las variables de programa. En lugar de parecer que se ejecutan dentro de un proceso o como una parte de él, los sondeos de DTrace se ejecutan en el núcleo de Solaris. Para acceder a los datos de proceso, un sondeo debe usar las subrutinas copyin() o copyinstr() para copiar los datos de proceso de usuario en el espacio de dirección del núcleo.

Por ejemplo, considere la siguiente llamada de sistema write(2):

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

El siguiente programa escrito en D ilustra un intento incorrecto de imprimir el contenido de una cadena pasada a la llamada de sistema write(2):

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

Si trata de ejecutar esta secuencia de comandos, DTrace generará mensajes de error similares al siguiente ejemplo:

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

La variable arg1, que contiene el valor del parámetro buf, es una dirección que hace referencia a la memoria en el proceso que ejecuta la llamada de sistema. Para leer la cadena de esta dirección, use la subrutina copyinstr() y registre el resultado con la acción printf():

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

El resultado de esta secuencia de comandos muestra todas las cadenas que se están pasando a la llamada de sistema write(2). Ocasionalmente, no obstante, puede observarse una salida irregular, semejante a la del siguiente ejemplo:

  0     37                      write:entry mada���

La subrutina copyinstr() actúa en un argumento de entrada que es la dirección del usuario de una cadena ASCII con una terminación nula. Sin embargo, las memorias intermedias pasadas a la llamada de sistema write(2) pueden hacer referencia a datos binarios en lugar de a cadenas ASCII. Para imprimir sólo las cadenas que el llamador desee, use la subrutina copyin(), que considera un tamaño como su segundo argumento:

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

Observe que el operador stringof es necesario para que DTrace convierta correctamente en una cadena los datos de usuario recuperados usando copyin. () El uso de stringof no es necesario cuando se emplea copyinstr(), ya que esta función siempre devuelve el tipo string.

Cómo evitar errores

Las subrutinas copyin() y copyinstr() no se pueden leer desde direcciones de usuario que no se hayan tocado todavía, por lo que incluso una dirección válida puede provocar un error si la página que contiene esa dirección no ha experimentado errores al acceder. Considere el siguiente ejemplo:

# 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

En la salida del ejemplo anterior, la aplicación funcionaba correctamente y la dirección de arg0 era válida, pero hacía referencia a una página a la que no había accedido todavía el proceso correspondiente. Para resolver este problema, espere a que el núcleo o la aplicación usen los datos antes de comenzar el seguimiento. Por ejemplo, puede esperar a que la llamada de sistema muestre su resultado para aplicar copyinstr(), tal y como se ilustra en el siguiente ejemplo:

# 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                        

Eliminación de la interferencia de dtrace(1M)

Si efectúa un seguimiento de todas las llamadas realizadas a la llamada de sistema write(2), provocará una cascada de resultados. Cada llamada realizada a write() provoca que el comando dtrace(1M) realice una llamada a write() cuando muestra la salida y así sucesivamente. El bucle de realimentación es un buen ejemplo de cómo el comando dtrace puede interferir con los datos deseados. Puede utilizar un predicado sencillo para impedir que se realice un seguimiento de estos datos no deseados:

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

La variable de macro $pid se expande hasta el identificador del proceso que activó los sondeos. La variable pid contiene el identificador del proceso cuyo subproceso se estaba ejecutando en la CPU cuando se activó el sondeo. En consecuencia, el predicado /pid != $pid/ garantiza que la secuencia de comandos no realiza ningún seguimiento de eventos relacionados con la secuencia de comandos en sí.

Proveedor syscall

El proveedor syscall le permite realizar un seguimiento de todas las entradas y las devoluciones de las llamadas de sistema. Las llamadas del sistema pueden ser un buen punto de partida para comprender el comportamiento de un proceso, especialmente si el proceso tarda mucho tiempo en las ejecuciones o queda bloqueado en el núcleo. Puede usar el comando prstat(1M) para ver dónde exactamente emplean el tiempo los procesos:

$ 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

Este ejemplo muestra que el proceso está gastando una cantidad grande del tiempo del sistema. Una posible explicación para este comportamiento es que el proceso está realizando una cantidad importante de llamadas del sistema. Puede usar un programa sencillo escrito en D especificado en la línea de comandos para ver qué llamadas del sistema se están produciendo con más frecuencia:

# 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

Este informe muestra qué llamadas del sistema se producen con más frecuencia; en este caso se trata de la llamada de sistema write(2). Puede usar el proveedor syscall para examinar en profundidad el origen de todas las llamadas del sistema 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 salida muestra que el proceso está ejecutando muchas llamadas del sistema write() con una cantidad de datos relativamente pequeña. Esta relación puede ser el origen de los problemas de rendimiento de este proceso concreto. En este ejemplo se muestra la metodología general para investigar el comportamiento de las llamadas del sistema.

Acción ustack()

El seguimiento de la pila del subproceso de un proceso en el momento en que se activa un sondeo concreto suele resultar útil para examinar un problema con mayor detalle. La acción ustack() realiza un seguimiento de la pila del subproceso del usuario. Si, por ejemplo, un proceso que abre varios archivos falla ocasionalmente en la llamada de sistema open(2), podrá usar la acción ustack() para descubrir la ruta de código que ejecuta la acción open() que ha fallado:

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();
}

Esta secuencia de comandos también ilustra el uso de la variable de macro $1 que toma el valor del primer operando especificado en la línea de comandos 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

La acción ustack() registra los valores del contador del programa (PC ) para la pila y dtrace(1M) resuelve estos valores PC en nombres de símbolos buscando en las tablas de símbolos del proceso. Si dtrace no puede resolver el valor PC en un símbolo, imprimirá el valor como un entero hexadecimal.

Si un proceso se cierra o se termina antes de que los datos de ustack() tengan el formato para la salida, es posible que dtrace no sea capaz de convertir los valores de PC del seguimiento de la pila en nombres de símbolos, por lo que estará obligado a mostrarlos como enteros hexadecimales. Para solucionar esta limitación, especifique un proceso de interés con la opción -c o -p para dtrace. Consulte el Capítulo 14Utilidad dtrace(1M) para obtener más información sobre estas y otras opciones. Si el ID del proceso o el comando no se conocen de antemano, se puede usar el siguiente programa escrito en D de ejemplo para solucionar esta limitación:

/*
 * 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;
}

La secuencia de comandos anterior detiene un proceso justo antes de que se cierre si la acción ustack() se ha aplicado a un subproceso de dicho proceso. Esta técnica garantiza que el comando dtrace esté disponible para resolver los valores PC en nombres simbólicos. Tenga en cuenta que el valor de stop_pids[pid] se establece en 0 después de que se haya usado para borrar la variable dinámica. Recuerde que debe ejecutar de nuevo los procesos detenidos usando el comando prun(1); de lo contrario, el sistema acumulará demasiados procesos detenidos.

Matriz uregs[]

La matriz uregs[] le permite acceder a registros de usuario individuales. En las siguientes tablas se muestran índices de la matriz uregs[] correspondientes a cada una de las arquitecturas de sistema Solaris admitidas.

En las plataformas AMD64, la matriz uregs tiene el mismo contenido que en las plataformas x86, además de los elementos adicionales que figuran en la siguiente tabla:

Los alias que aparecen en la siguiente tabla se pueden usar en todas las plataformas:

Proveedor pid

El proveedor pid permite realizar un seguimiento de cualquier instrucción en un proceso. A diferencia de otros proveedores, los sondeos pid se crean a petición basándose en las descripciones de sondeos que se encuentran en los programas escritos en D. Como resultado, ningún sondeo pid aparece en la salida de dtrace-l hasta que los haya activado.

Seguimiento de los límites de la función de usuario

El modo más sencillo de funcionamiento del proveedor pid es actuar como espacio de usuario análogo al proveedor fbt. El siguiente programa de ejemplo realiza un seguimiento de todas las entradas de funciones y devuelve las que están compuestas de una única función. La variable de macro $1 (el primer operando de la línea de comandos) es el ID de proceso para el proceso que se debe seguir. La variable de macro $2 (el segundo operando de la línea de comandos) es el nombre de la función desde la que se deben seguir todas las llamadas a funciones.

Ejemplo 33–1 userfunc.d: seguimiento de la entrada y devolución de una función de usuario

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

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

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

Escriba la secuencia de comandos de ejemplo anterior y guárdela en un archivo que se llame userfunc.d y, a continuación, aplique chmod para que sea ejecutable. Esta secuencia de comandos genera un resultado similar al siguiente ejemplo:

# ./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                        
...

El proveedor pid sólo se puede usar en procesos que ya se estén ejecutando. Puede usar la variable de macro $target (consulte el Capítulo 15Secuencias de comandos), y las opciones dtrace -c y -p para crear y obtener procesos de interés e instrumentarlos usando DTrace. Por ejemplo, la siguiente secuencia de comandos en D se puede usar para determinar la distribución de las llamadas a funciones que un proceso de sujeto concreto realiza a libc:

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

Para determinar la distribución de este tipo de llamadas realizadas mediante el comando date(1), guarde la secuencia de comandos en un archivo llamado libc.d y ejecute el siguiente comando:

# 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

Seguimiento de instrucciones arbitrarias

Puede usar el proveedor pid para realizar un seguimiento de instrucciones en cualquier función de usuario. A petición, el proveedor pid creará un sondeo para cada instrucción de una función. El nombre de cada sondeo es el desplazamiento de su instrucción correspondiente en la función expresada como un entero hexadecimal. Por ejemplo, para activar un sondeo asociado a la instrucción del desplazamiento 0x1c en la función foo del módulo bar.so en el proceso cuyo PID sea 123, deberá usar el siguiente comando:

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

Para activar todos los sondeos de la función foo, incluido el sondeo para cada instrucción, puede usar el siguiente comando:

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

Este comando muestra una técnica realmente eficaz para depurar y analizar aplicaciones de usuario. Los errores poco frecuentes pueden ser difíciles de depurar porque pueden ser complicados de reproducir. A menudo, se identifica un error después de que se produzca, por lo que es demasiado tarde para reconstruir la ruta del código. El siguiente ejemplo muestra cómo se combina el proveedor pid con seguimientos especulativos (consulte el Capítulo 13Seguimiento especulativo) para resolver este problema realizando el seguimiento de todas las instrucciones de una función.

Ejemplo 33–2 errorpath.d: seguimiento de la ruta de error de una llamada de función de usuario

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;
}

La ejecución de errorpath.d da como resultado una salida similar a la siguiente:

# ./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