forondarenanet

Update: La versión de github del script ya es capaz de monitorizar n pids en ejecución y n programas que todavía no lo estén.

Para retomar un poco el blog, y como hace mucho que no escribo nada sobre SystemTap, me he planteado otro sencillo ejercicio “de repaso”.

La verdad es que en la actualidad ya hay un buen montón de artículos, documentación y ejemplos sobre lo que se puede hacer con SystemTap, ya sea para la inspección del kernel como para la de aplicaciones tipo mysql, postgresql o python. El rpm de Scientific Linux 6, por ejemplo, incluye más de 80 ejemplos de todo tipo, desde el análisis de procesos hasta el del tráfico de red.

Aún así, como digo, aquí va un ejemplo más.

El problema
Vamos a suponer que tenemos un proceso ejecutando en una máquina, y que queremos vigilar los ficheros que va abriendo.

Para ir un poco más lejos, queremos que se muestren también los ficheros abierto por los hijos de ese proceso principal (sólo un nivel por ahora).

Y ya puestos, queremos poder limitar la monitorización a los ficheros de ciertas rutas. Por ejemplo, podemos querer mostrar sólo los ficheros que se abrán en /etc, o en /lib.

Vamos, que el ejercicio es prácticamente una extensión de uno de los scripts de un post anterior de este mismo blog. Pero que le voy a hacer, sólo se me ocurren ejercicios sobre ficheros.

Resumiendo, y poniendo un ejemplo, tenemos un servidor postfix, con sus habituales procesos hijo:

master─┬─pickup
       │─qmgr
       └─tlsmgr

Queremos saber que ficheros abren todos los procesos que cuelgan de master, ya sean los tres que se están ejecutando en este momento, ya sean los nuevos que se vayan creando. Además, queremos poder limitar el número de ficheros vigilados a una serie de rutas determinadas.

La solución
El núcleo de la solución está en dos “probes”:

• syscall.open.return
• syscall.close.return

O sea, las llamadas al sistema open y close. Más concretamente, al momento en el que terminan de ejecutarse (return).

Además, vamos a usar el probe “begin” para leer argumentos, preparar variables y demás parafernalia.

Comenzamos:

probe begin {
        procesoArgumento = $1
        printf ("El pid que vamos a tratar es %d\n", procesoArgumento);
        if (argc > 1) {
                for (i=2; i <= argc; i++) {
                        ficherosEnPath[argv[i]] = argv[i]
                        numeroPaths += 1
                }
        }
}

Poca explicación hace falta. En $1 tenemos el primer argumento, que va a ser el pid a vigilar. A partir del segundo argumento, y de manera opcional, se pueden incluir una serie de rutas a monitorizar. Todas estas son llamadas válidas:

stap -v monitorFicheros.stp $(pidof master)
stap -v monitorFicheros.stp $(pidof master) /etc
stap -v monitorFicheros.stp $(pidof master) /etc /usr/lib

Una vez definido este bloque básico, pasamos a la llamada al sistema "open":

probe syscall.open.return {
        proceso = pid()
        padre = ppid()
        hilo = tid()
        ejecutable = execname()
        insertarEnTabla = 0

        if ( (procesoArgumento == proceso) || (procesoArgumento == padre) || (procesoArgumento == hilo) ) {
                if ( (procesoArgumento == proceso) && (env_var("PWD") != "") ) {
                        pwd = env_var("PWD")
                }
                localpwd = (isinstr(env_var("PWD"), "/"))?env_var("PWD"):pwd;

                filename = user_string($filename)
                descriptor = $return

                filename = (substr(filename, 0, 1) == "/")?filename:localpwd . "/" . filename;

                if ([proceso,padre,hilo,descriptor] in tablaProcesos)  {
                        printf ("{codigo: \"error\", proceso: \"%s\", pid: %d, ppid: %d, tid: %d, fichero: \"%s\", descriptor: %d}\n", ejecutable, proceso, padre, hilo, filename, descriptor)
                } else {
                        if (descriptor >= 0) {
                                if (numeroPaths > 0 ) {
                                        foreach (ruta in ficherosEnPath) {
                                                if (substr(filename, 0, strlen(ruta)) == ruta) {
                                                        insertarEnTabla = 1
                                                        break
                                                }
                                        }
                                }
                                if ( (insertarEnTabla == 1) || (numeroPaths == 0) ) {
                                        tablaProcesos[proceso,padre,hilo,descriptor] = gettimeofday_ms()
                                        tablaFicheros[proceso,padre,hilo,descriptor] = filename
                                        printf ("{codigo: \"open\", proceso: \"%s\", pid: %d, ppid: %d, tid: %d, fichero: \"%s\", descriptor: %d, date: %d}\n", ejecutable, proceso, padre, hilo, filename, descriptor, tablaProcesos[proceso,padre,hilo,descriptor])
                                }
                        }
                }
        }
}

A través de las funciones pid(), ppid() y tid() vemos si el proceso que está ejecutando open en este momento es el proceso que nos interesa o un hijo suyo.

Si cumple este requerimiento, pasamos al bloque que revisa si el fichero que se está abriendo está en el path que nos interesa. En este caso, para hacer el ejercicio más completo, he optado por dar unas cuantas vueltas "de más", y he usado la función env_var("PWD") para acceder al entorno del proceso. En la práctica esta no es la mejor forma, y por eso hay más control en el probe, ya que no siempre existe la variable PWD en el entorno de los procesos que llegan a este open.

La llamada al sistema open carga las variables $return (el valor de retorno de la función es el id del descriptor del fichero) y $filename (el nombre del fichero). Ojo! Cada llamada al sistema tiene unos argumentos, y con ello "ofrece" unas variables para nuestros scripts. Por ejemplo, mientras que en open tenemos filename, flags y mode; en close tenemos fd, filp, files, fdt y retval. El propio SystemTap, Google y el código fuente del kernel son ... vuestros amigos.

En cualquier caso, lo importante es que, cuando se dan todas las condiciones, hacemos lo siguiente:

tablaProcesos[proceso,padre,hilo,descriptor] = gettimeofday_ms()
tablaFicheros[proceso,padre,hilo,descriptor] = filename
printf ("{codigo: \"open\", proceso: \"%s\", pid: %d, ppid: %d, tid: %d, fichero: \"%s\", descriptor: %d, date: %d}\n", ejecutable, proceso, padre, hilo, filename, descriptor, tablaProcesos[proceso,padre,hilo,descriptor])

Con el printf escribimos la información del fichero abierto por salida estándar. Las dos tablas (tablaProcesos y tablaFicheros) sirven para guardar el momento en el que se ha abierto el fichero (con una precisión de milisegundos), y el nombre del fichero en sí mismo, con lo que lo tendremos más a mano cuando pasemos a la llamada al sistema close. Para identificar un fichero usamos el índice formado con [el proceso, el padre, el hilo y el descriptor] del fichero que se ha abierto.

Con toda la información en su sitio ya tenemos la primera parte del script. Seguimos:

probe syscall.close.return {
        proceso = pid()
        padre = ppid()
        hilo = tid()
        descriptor = $fd
        ejecutable = execname()

        if ( ( procesoArgumento == proceso ) || ( procesoArgumento == padre ) || (procesoArgumento == hilo ) ) {
                if ([proceso,padre,hilo,descriptor] in tablaProcesos) {
                        filename = tablaFicheros[proceso,padre,hilo,descriptor]
                        date = gettimeofday_ms() - tablaProcesos[proceso,padre,hilo,descriptor]
                        printf ("{codigo: \"close\", proceso: \"%s\", pid: %d, ppid: %d, tid: %d, fichero: \"%s\", descriptor: %d, date: %d}\n", ejecutable, proceso, padre, hilo, filename, descriptor, date)
                        delete tablaProcesos[proceso,padre,hilo,descriptor]
                        delete tablaFicheros[proceso,padre,hilo,descriptor]
                }
        }
}

Fácil. Si se está haciendo un close de uno de los ficheros monitorizados, se calcula el tiempo que ha estado abierto y se muestra por la salida estándar.

Un ejemplo de ejecución del monitor es el siguiente:

# stap -v monitorFicheros.stp $(pidof master)
Pass 1: parsed user script and 76 library script(s) using 96688virt/22448res/2744shr kb, in 120usr/10sys/133real ms.
Pass 2: analyzed script: 8 probe(s), 22 function(s), 7 embed(s), 8 global(s) using 251840virt/48200res/3952shr kb, in 420usr/120sys/551real ms.
Pass 3: using cached /root/.systemtap/cache/02/stap_02e370ac4942b188c248e7ec11ac8e2c_19586.c
Pass 4: using cached /root/.systemtap/cache/02/stap_02e370ac4942b188c248e7ec11ac8e2c_19586.ko
Pass 5: starting run.

El pid que vamos a tratar es 1082
{codigo: "open", proceso: "smtpd", pid: 5817, ppid: 1082, tid: 5817, fichero: "/etc/hosts", descriptor: 12, date: 1310920975000}
{codigo: "close", proceso: "smtpd", pid: 5817, ppid: 1082, tid: 5817, fichero: "/etc/hosts", descriptor: 12, date: 0}

Sorpresa! Los printf se formatéan como datos json, por si alguna vez quisiera hacer algo con node.js y aplicaciones como log.io.

En cuanto a los "date: 0", se debe a que la precisión de milisegundos es demasiado baja para estos ficheros y para esta prueba sin tráfico de correo de ningún tipo.

El código completo (en este post sólo falta la definición de variables globales) está accesible en github, como siempre.

Limitaciones y trabajo futuro
Como ya he comentado, este script está lejos de ser óptimo. Además de mi propia incapacidad, en algunos momentos he optado por dar más vueltas de las necesarias para usar así más funciones y variables.

Mi primer objetivo era permitir la monitorización de procesos que todavía no estuvieran en ejecución. En esta versión, sin embargo, el proceso principal sí tiene que estar ejecutando antes de lanzar el stap. Esto no es algo técnicamente complicado, pero no se hace solo, y no aporta demasiado desde el punto de vista conceptual al post, así que lo he dejado.

¿Y qué pasa si el pidof da más de un pid? Me habéis pillado. Por ahora sólo trato un pid.

Para el que esté interesado, SystemTap permite guardar la salida estándar en un fichero usando el parámetro -o. A partir de aquí es trivial que otro script perl, python, bash, node.js o lo que sea trabaje con él.

A veces (seguro que pocas), nos encontramos ante una máquina que por algún motivo ha dejado de trabajar como se esperaba.
Digamos que el rendimiento o el IO del equipo baja, sin motivo visible. Digamos que no hay logs que indiquen problemas, ni errores del sistema. Nada.
Este es el momento para el kung fu, el voodoo o todo tipo de técnicas adivinatorias que tanto usamos los informáticos. Muchas veces es suficiente, pero no siempre, y no hay nada peor que no ser capaz de dar una explicación a un problema.

Supongamos que tenemos la arquitectura de la imagen, con un par de balanceadores de carga, unas cuantas máquinas iguales que pueden ser servidores web, ftp, pop, smtp o cualquier otra cosa, y un par de servidores de almacenamiento nfs.
Teniendo en cuenta que los balanceadores de carga suelen dar la posibilidad de asignar diferentes pesos a cada máquina balanceada, ¿Por qué no usar uno de estos servidores para la monitorización del sistema? Es perfectamente posible enviar un poco menos de tráfico a la máquina destinada a SystemTap, de tal manera que no afecte al rendimiento global, para que podamos darnos un mecanismo para tener nuestra infraestructura controlada.

En este post sólo voy a referenciar algunos scripts que están disponibles en la web y en el redpaper. Además, el propio software viene con muchos ejemplos. En CentOS se puede instalar el rpm “systemtap-testsuite” para probar varios scripts.

Vamos a empezar con un par de ejemplos para usar más en un entorno académico que en la práctica.

Digamos que queremos aprender “lo que pasa” cuando hacemos un “ls” en un directorio de una partición ext3. Con este sencillo script:

#! /usr/bin/env stap

probe module("ext3").function("*").call
{
   printf("%s -> %s\n", thread_indent(1), probefunc())
}
probe module("ext3").function("*").return
{
   printf("%s <- %s\n", thread_indent(-1), probefunc())
}

Vamos a hacer un printf cada vez que comience y termine la ejecución de cualquier función del módulo ext3. En el printf vamos a tabular el nombre de la función que se ha ejecutado. El resultado es algo así:

   ...
     2 ls(31789): <- ext3_permission
     0 ls(31789): -> ext3_dirty_inode
     8 ls(31789):  -> ext3_journal_start_sb
    21 ls(31789):  <- ext3_journal_start_sb
    26 ls(31789):  -> ext3_mark_inode_dirty
    31 ls(31789):   -> ext3_reserve_inode_write
    35 ls(31789):    -> ext3_get_inode_loc
    39 ls(31789):     -> __ext3_get_inode_loc
    52 ls(31789):     <- __ext3_get_inode_loc
    56 ls(31789):    <- ext3_get_inode_loc
    61 ls(31789):   <- ext3_reserve_inode_write
    67 ls(31789):   -> ext3_mark_iloc_dirty
    74 ls(31789):   <- ext3_mark_iloc_dirty
    77 ls(31789):  <- ext3_mark_inode_dirty
    83 ls(31789):  -> __ext3_journal_stop
    87 ls(31789):  <- __ext3_journal_stop
    90 ls(31789): <- ext3_dirty_inode
     0 ls(31789): -> ext3_permission
   ...

Como he dicho, no es algo demasiado práctico, pero puede servir a algún profesor para suspender a un buen porcentaje de pobres alumnos
Sigamos con algún otro ejemplo. Digamos que queremos programar un "nettop" que nos diga qué conexiones se están abriendo en una máquina en cada momento. Con un script similar al siguiente lo tendremos en unos minutos:

#! /usr/bin/env stap

global ifxmit, ifrecv

probe netdev.transmit
{
  ifxmit[pid(), dev_name, execname(), uid()] <<< length
}

probe netdev.receive
{
  ifrecv[pid(), dev_name, execname(), uid()] <<< length
}

function print_activity()
{
  printf("%5s %5s %-7s %7s %7s %7s %7s %-15s\n",
         "PID", "UID", "DEV", "XMIT_PK", "RECV_PK",
         "XMIT_KB", "RECV_KB", "COMMAND")

  foreach ([pid, dev, exec, uid] in ifrecv-) {
    n_xmit = @count(ifxmit[pid, dev, exec, uid])
    n_recv = @count(ifrecv[pid, dev, exec, uid])
    printf("%5d %5d %-7s %7d %7d %7d %7d %-15s\n",
           pid, uid, dev, n_xmit, n_recv,
           n_xmit ? @sum(ifxmit[pid, dev, exec, uid])/1024 : 0,
           n_recv ? @sum(ifrecv[pid, dev, exec, uid])/1024 : 0,
           exec)
  }
  print("\n")
  delete ifxmit
  delete ifrecv
}

probe timer.ms(5000), end, error
{
  print_activity()
}

¿Qué es lo que hemos hecho? Hemos generado tres "probes". Por un lado, cuando se recibe o trasmite a través de la red añadimos a los arrays "ifxmit, ifrecv" información sobre qué proceso y en qué interfaz ha enviado o recibido. Por otro lado, cada 5000 ms o cuando haya un error o termine el script mostramos la información por pantalla. El resultado puede ser algo similar a lo siguiente:

  PID   UID DEV     XMIT_PK RECV_PK XMIT_KB RECV_KB COMMAND
31485   500 eth0          1       1       0       0 sshd           

y pasados unos miles de milisegundos ...

  PID   UID DEV     XMIT_PK RECV_PK XMIT_KB RECV_KB COMMAND
15337    48 eth0          4       5       5       0 httpd
31485   500 eth0          1       1       0       0 sshd

Como se ve, tengo una sesión ssh abierta permanentemente, y he consultado una página web en el servidor monitorizado.
Por supuesto, esto puede no ser muy práctico en servidores muy activos, pero puede dar alguna idea a algún administrador.
Igual que hemos hecho un "nettop", también podemos hacer un "disktop" que muestre un resultado como el siguiente:

Sat Apr 11 17:22:03 2009 , Average:   0Kb/sec, Read:       0Kb, Write:      0Kb
     UID      PID     PPID                       CMD   DEVICE    T        BYTES
      48    15342    15239                     httpd     dm-0    W          210
      48    15343    15239                     httpd     dm-0    W          210
      48    15337    15239                     httpd     dm-0    W          210
      48    15336    15239                     httpd     dm-0    W          210

Lo que hecho es hacer el mismo wget varias veces. Para el que tenga curiosidad, los procesos httpd (que por cierto usa el usuario id=48) ejecutando en el servidor son:

# pstree -p | grep http
        |-httpd(15239)-+-httpd(15336)
        |              |-httpd(15337)
        |              |-httpd(15338)
        |              |-httpd(15339)
        |              |-httpd(15340)
        |              |-httpd(15341)
        |              |-httpd(15342)
        |              `-httpd(15343)

El script disktop está disponible en "/usr/share/systemtap/testsuite/systemtap.examples/io" del rpm "systemtap-testsuite".

Volvamos al primer ejemplo del post. Teníamos un grupo de servidores que han dejado de funcionar como deben. Digamos que sospechamos de la velocidad con la que nuestros servidores nfs están sirviendo el contenido de los servidores web.
Podemos probar aquellos ficheros que necesiten más de 1 segundo para abrirse:

#!/usr/bin/stap

global open , names
probe begin {
        printf("%10s %12s %30s\n","Process" , "Open time(s)" , "File Name")
}
probe kernel.function("sys_open").return{
        open[execname(),task_tid(task_current()),$return] = gettimeofday_us()
        names[execname(),task_tid(task_current()),$return] = user_string($filename)
}
probe kernel.function("sys_close"){
        open_time_ms = (gettimeofday_us() - open[execname(),task_tid(task_current()), $fd])
        open_time_s = open_time_ms / 1000000
        if ((open_time_s >= 1) && (names[execname(),task_tid(task_current()), $fd] != "")) {
                printf("%10s %6d.%.5d %30s\n", execname(),
open_time_s,open_time_ms%1000000,names[execname(),task_tid(task_current()), $fd])
        }
}

Con este sencillo script estaría hecho:

   Process Open time(s)                      File Name
     httpd      8.471285 /var/www/html/lectura_lenta.html

En este caso al servidor web le ha costado 8.5 segundos servir el fichero lectura_lenta.html. Después será responsabilidad nuestra buscar los problemas.

En definitiva, systemtap es una herramienta muy completa, pero que como tal requiere algo de práctica para ser útil. No sé si alguna vez va a tener mucho éxito en entornos de producción, pero no está de más saber que existe.