Introducción a BPF

lun, 04 sep 2017 by Foron

Aquí va otro post sin grandes cosas que aportar a los ya iniciados, pero que sí puede servir a todos aquellos que no conocen qué es el nuevo BPF; en su inicio eBPF (extended Berkeley Packet Filter), pero que cada vez más va pasando a ser, simplemente, BPF.

La inmensa mayoría de lo que voy a escribir no es contenido original. Consideradlo una introducción en la que os mostraré varios ejemplos de desarrollos ya hechos. Por supuesto, trataré de dar referencias de toda la documentación que voy a usar en este post.

¿Qué es BPF?

Hablemos del antiguo BPF, del original.

Brevemente, porque todas las presentaciones que podáis ver sobre el tema ya hacen una introducción, BPF fue un esfuerzo de allá por el 1992 para evitar la transferencia de paquetes, sobre todo de red, desde el Kernel al entorno de usuario. El objetivo era generar un bytecode seguro que pudiese ejecutarse lo más cerca posible de la red. La mayoría habéis hecho cosas tipo tcpdump -i eth0 "port 80". Internamente, y pecando de básico, ese filtro "port 80" se escribia de tal manera que pudiese engancharse al socket y así procesarse más eficientemente.

En el 2013, con Alexei Starovoitov como cabeza más visible, se dio una vuelta a este concepto y se comenzó el trabajo en el nuevo BPF. Como comentaba, todas las charlas que veáis tienen una introducción, así que mejor un par de enlaces, intro 1 y intro 2, que repetir lo que ya se ha dicho. En todo caso, resumiéndolo todo mucho, y con el riesgo de que simplificar demasiado me haga escribir algo incorrecto, lo que permite BPF es añadir código que se va a ejecutar en el Kernel ante ciertos "eventos". Dicho de otra forma, podemos ejecutar nuestro código cuando el Kernel llame o salga de las funciones tcp_v4_connect o ext4_file_open, por poner dos ejemplos. Pero no solo esto; también se pueden instrumentalizar sockets, librerías o aquellas aplicaciones que lo permitan.

Traducido a algunos ejemplos, con BPF pod(r)emos:

  • Ejecutar código para la gestión de red en las capas más bajas del Kernel. XDP (eXpress Data Path) es el nombre clave que conocer aquí (intro 3 , intro 4 e intro 5). Los usos son variados; Facebook ya están documentando que empiezan a usarlo para el balanceo de carga, otros como Cloudflare en entornos anti DDoS, tc ya tiene un clasificador basado en BPF, o el proyecto Cillium, cada vez más conocido, que está más orientado a contenedores. En realidad, no sería raro pensar que una buena parte del software que usamos en estos entornos (quizá incluyendo Open vSwitch y similares) pasen a usar BPF en mayor o menor medida en un futuro no muy lejano.
  • Pasar del entorno del Kernel al espacio de usuario para instrumentalizar librerías. Uno de los ejemplos ya disponibles del uso de uprobes muestra cómo podríamos capturar el tráfico HTTPS de un servidor web justo antes de ser cifrado. Veremos el script más adelante, pero básicamente lo que se hace es incluir nuestro código en las llamadas a SSL_read y SSL_write de openssl.
  • Usar la funcionalidad que ofrecen muchas de las aplicaciones más importantes que usamos habitualmente, com Mysql, Postgresql o lenguajes de programación como Java, Ruby, Python o Node, para conocer al detalle lo que está ocurriendo cuando se ejecutan. Las USDT (User Statically Defined Tracing) se han venido usando con Dtrace y SystemTap, y ahora también con BPF.

He dejado para el final el caso de uso seguramente más documentado. La monitorización y el análisis de rendimiento tienen ya decenas de scripts listos para su uso. Veamos algunos ejemplos.

Ejemplos

No voy a dedicar ni una línea a la instalación del software. Con la llegada de las últimas versiones estábles de las distribuciones Linux, en muchos casos con versiones de Kernel a partir de 4.9, tenemos una versión que suele recomendarse para tener ya la mayoría de funcionalidades. Esto en lo que al Kernel se refiere. El resto de utilidades alrededor de esta base se instalará en función de la distribución que uséis. Con Ubuntu puede ser tan sencillo como un apt-get install, y con otras podría obligaros a trabajar un poco más. Aquí tenéis algunas instrucciones.

Si alguno habéis seguido este último enlace, habréis visto que hemos pasado del acrónimo BPF a BCC. En el paquete BPF Compiler Collection tenemos todo lo necesario para que escribir código BPF sea más fácil. Para los que no somos capaces de escribir 20 líneas en C sin tener algún segmentation fault, lo mejor que nos ofrece este toolkit son a) aplicaciones ya hechas y b) la posibilidad de integrar el código que se ejecuta en el Kernel en scripts Python o Lua, además del propio C++. Últimamente también se está dando soporte a Go, pero no os puedo dar muchos más detalles porque no lo he probado.

Resumiendo, para los vagos, los que no tienen tiempo o los que no se ven capaces de escribir esa parte en C de la que os he hablado, BCC nos permite usar y aprender de los scripts que va publicando la comunidad en los directorios de herramientas y de ejemplos, y adaptarlos a nuestro entorno que, muchas veces, solo implicará escribir Python.

Para los que os veáis más capaces, un buen primer paso es leer este tutorial y la guía de referencia. Merece la pena tener ambos enlaces siempre a mano.

Imaginad, por ejemplo, que queréis registrar todo lo que se ejecuta en vuestras máquinas. Los ejemplos incluidos en el repositorio de BCC incluyen un script para mostrar lo que se lanza desde bash, y otro para lo que se ejecuta vía exec. Como bashreadline.py es más sencillo de leer, vamos a centrarnos en hacer un history remoto.

El esqueleto básico de todos los scripts es el siguiente:

  1. Import de la clase BPF
  2. Preparar el código C, ya sea vía fichero externo o como una variable de texto
  3. Crear una instancia de BPF haciendo referencia al código C
  4. Definir dónde (kprobe, uprobe, ...) queremos ejecutar las funciones C que hemos escrito
  5. Usar los recursos que ofrece la instancia BPF para trabajar con lo que va devolviendo el Kernel.

En el caso de bashreadline.py, y quitando lo menos relevante en este momento:

bpf_text = """
    #include <uapi/linux/ptrace.h>
    struct str_t {
        u64 pid;
        char str[80];
    };
    BPF_PERF_OUTPUT(events);

    int printret(struct pt_regs *ctx) {
        struct str_t data  = {};
        u32 pid;
        if (!PT_REGS_RC(ctx)) return 0;
        pid = bpf_get_current_pid_tgid();
        data.pid = pid;
        bpf_probe_read(&data.str, sizeof(data.str), (void *)PT_REGS_RC(ctx));
        events.perf_submit(ctx,&data,sizeof(data));
        return 0;
    };
"""

from bcc import BPF
bpf_text = """ ... """

b = BPF(text=bpf_text)
b.attach_uretprobe(name="/bin/bash", sym="readline", fn_name="printret")

def print_event(cpu, data, size):
    event = ct.cast(data, ct.POINTER(Data)).contents
    print("%-9s %-6d %s" % (strftime("%H:%M:%S"), event.pid, event.str.decode()))

b["events"].open_perf_buffer(print_event)
while 1:
    b.kprobe_poll()

El script original no llega a 60 líneas, así que no penséis que me haya comido demasiado. Si lo ejecutáis, veréis todo lo que se está ejecutando desde todos los bash de la máquina:

# ./bashreadline
TIME      PID    COMMAND
05:28:25  21176  ls -l
05:28:28  21176  date
05:28:35  21176  echo hello world
05:28:43  21176  foo this command failed

Nada os impide editar este código, así que ¿Por qué no cambiar ese print de print_event por algo que escriba en un syslog o un graphite remoto? Yo por ejemplo uso mucho ZeroMQ para estas cosas:

import zmq
contexto = zmq.Context()
eventos = contexto.socket(zmq.REQ)
eventos.connect("tcp://172.16.1.2:7658")
...
salida = print("%-9s %-6d %s" % (strftime("%H:%M:%S"), event.pid, event.str.decode()))
eventos.send_string(salida)
eventos.recv()

Vamos, que con 6 líneas (dejando a un lado el servidor escuchando en 172.16.1.2:7658), nos hemos hecho un history remoto.

Independientemente de lo útil que os haya parecido esto, ya veis que es muy fácil adaptar los scripts y hacer cosas realmente interesantes.

Vamos a ver algunos ejemplos de scripts. Todo está en github, así que podéis ir allí directamente.

Pregunta típica: ¿Cuál es el rendimiento de nuestro sistema de ficheros ext4?

El rendimiento de los dispositivos de bloque y de los diferentes sistemas de ficheros es uno de los temas más tratados entre las herramientas que ya tenemos disponibles. Hay scripts para ver la distribución de las latencias en un sistema o para hacer cosas parecidas al comando top (ejemplo top) y responder a la pregunta ¿Quién está accediendo a dispositivo en este momento? También los tenemos para mostrar distribuciones de latencias (ejemplo latencias) en un periodo de tiempo, o para analizar los sistemas de ficheros más habituales. Para ext4, por ejemplo, podemos usar ext4slower (ejemplo ext4slower) para ver qué reads, writes, opens y syncs han ido lentas, o ext4dist (ejemplo ext4dist) para ver un histograma con la distribución de las latencias de estas operaciones. En ext4slower.py, por ejemplo, se instrumentaliza la entrada y la salida de estas funciones (mirad el argumento event=)

...
# initialize BPF
b = BPF(text=bpf_text)

# Common file functions. See earlier comment about generic_file_read_iter().
b.attach_kprobe(event="generic_file_read_iter", fn_name="trace_read_entry")
b.attach_kprobe(event="ext4_file_write_iter", fn_name="trace_write_entry")
b.attach_kprobe(event="ext4_file_open", fn_name="trace_open_entry")
b.attach_kprobe(event="ext4_sync_file", fn_name="trace_fsync_entry")
b.attach_kretprobe(event="generic_file_read_iter", fn_name="trace_read_return")
b.attach_kretprobe(event="ext4_file_write_iter", fn_name="trace_write_return")
b.attach_kretprobe(event="ext4_file_open", fn_name="trace_open_return")
b.attach_kretprobe(event="ext4_sync_file", fn_name="trace_fsync_return")
...

Aunque estos scripts son un poco más difíciles de leer, si habéis echado un ojo al tutorial y a la referencia del principio del post los podréis seguir fácilmente.

El uso de la CPU es otra área muy trabajada. Aunque siempre ha habido herramientas para su análisis (no siempre se ha hecho bien), con BPF se han mejorado mucho. Un buen ejemplo son los flame graphs. Aunque la pregunta principal siempre ha sido ¿Qué está haciendo la CPU ahora?, con los últimos desarrollos que se están haciendo podéis ver tranquilamente tanto el tiempo "On-CPU" como "Off-CPU" de las tareas. Dicho de otra forma, podéis saber cuánto tiempo pasa el comando tar ejecutándose, y cuánto esperando a disco. Como vamos a ver más scripts en este post, en lugar de ver los ejemplos (que los hay, y muchos) para instrumentalizar el scheduler y todo lo relacionado con la ejecución de tareas, os voy a dar el enlace a una fantástica presentación de Brendan Gregg donde podéis ver mucho de lo que se puede hacer hoy en día con los Flame Graphs, ya sea vía BPF o vía perf. Os recomiendo que dediquéis un poco de tiempo a esto, porque es realmente interesante. Intenet está llena de referencias, así que ya tenéis un pasatiempo para un rato.

Nos saltamos la CPU y pasamos, por ejemplo, al análisis del uso de memoria.

Pongámonos en el escenario de un entorno en el que el consumo de memoria de una máquina va subiendo y subiendo. Una opción para tratar de ver si hay algo raro en la asignación de memoria es el script memleak (ejemplo memleak). Otra alternativa, como veremos más adelante, es centrar la investigación más en las propias aplicaciones.

Vamos a ver algo más de código. Digamos que queremos saber si estamos haciendo un uso eficiente de la memoria Cache. Justo para esto tenemos cachetop (ejemplo cachetop). La parte escrita en C es sencilla, una única función:

bpf_text = """
#include <uapi/linux/ptrace.h>
struct key_t {
    u64 ip;
    u32 pid;
    u32 uid;
    char comm[16];
};
BPF_HASH(counts, struct key_t);
int do_count(struct pt_regs *ctx) {
    struct key_t key = {};
    u64 zero = 0 , *val;
    u64 pid = bpf_get_current_pid_tgid();
    u32 uid = bpf_get_current_uid_gid();
    key.ip = PT_REGS_IP(ctx);
    key.pid = pid & 0xFFFFFFFF;
    key.uid = uid & 0xFFFFFFFF;
    bpf_get_current_comm(&(key.comm), 16);
    val = counts.lookup_or_init(&key, &zero);  // update counter
    (*val)++;
    return 0;
}
"""

A la que se hace referencia en la parte en Python:

...
b = BPF(text=bpf_text)
b.attach_kprobe(event="add_to_page_cache_lru", fn_name="do_count")
b.attach_kprobe(event="mark_page_accessed", fn_name="do_count")
b.attach_kprobe(event="account_page_dirtied", fn_name="do_count")
b.attach_kprobe(event="mark_buffer_dirty", fn_name="do_count")
...

Como veis, el mismo esquema que hasta ahora. El resultado nos muestra el porcentaje de acierto en Cache. Ejecutemos un find / mientras tenemos ejecutando el script:

# ./cachetop.py
13:01:01 Buffers MB: 76 / Cached MB: 114 / Sort: HITS / Order: ascending
PID      UID      CMD              HITS     MISSES   DIRTIES  READ_HIT%  WRITE_HIT%
...
984 vagrant  find                 9529     2457        4      79.5%      20.5%

Si ejecutamos una segunda vez ese mismo find /, veremos que el uso del Cache es mucho mś eficiente:

# ./cachetop.py
13:01:01 Buffers MB: 76 / Cached MB: 115 / Sort: HITS / Order: ascending
PID      UID      CMD              HITS     MISSES   DIRTIES  READ_HIT%  WRITE_HIT%
...
1071 vagrant  find                12959        0        0     100.0%       0.0%

Con esto terminamos esta parte. Recordad, tenéis muchos más ejemplos en el repositorio de github.

Hasta ahora, con la excepción de bashreadline.py, hemos estado muy centrados en el propio Kernel. En la introducción hemos visto que BPF permite subir un poco y llegar a librerías y aplicaciones.

Cuando subimos al userspace y a las librerías, en este caso concreto, entramos en el terreno de las uprobes. En el repositorio de BCC hay un ejemplo muy gráfico de lo que se puede hacer, por ejemplo, para la instrumentalización de la librería openssl. Al principio del post ya hemos hablado, muy por encima, de sslsniff (ejemplo sslsniff). La estructura es parecida a los kprobes, aunque en este caso instrumentalizamos las llamadas a librería:

...
b = BPF(text=prog)

# It looks like SSL_read's arguments aren't available in a return probe so you
# need to stash the buffer address in a map on the function entry and read it
# on its exit (Mark Drayton)
#
if args.openssl:
    b.attach_uprobe(name="ssl", sym="SSL_write", fn_name="probe_SSL_write",
                    pid=args.pid or -1)
    b.attach_uprobe(name="ssl", sym="SSL_read", fn_name="probe_SSL_read_enter",
                    pid=args.pid or -1)
    b.attach_uretprobe(name="ssl", sym="SSL_read", fn_name="probe_SSL_read_exit", pid=args.pid or -1)
...

probe_SSL_write es la función en C del script para, en este caso, la entrada a SSL_write de libssl.

...
int probe_SSL_write(struct pt_regs *ctx, void *ssl, void *buf, int num) {
    u32 pid = bpf_get_current_pid_tgid();
    FILTER
    struct probe_SSL_data_t __data = {0};
    __data.timestamp_ns = bpf_ktime_get_ns();
    __data.pid = pid;
    __data.len = num;
    bpf_get_current_comm(&__data.comm, sizeof(__data.comm));
    if ( buf != 0) {
            bpf_probe_read(&__data.v0, sizeof(__data.v0), buf);
    }
    perf_SSL_write.perf_submit(ctx, &__data, sizeof(__data));
    return 0;
}
...

Al final, el resultado del script completo es que somos capaces de ver en texto plano lo que entra en libssl desde, por ejemplo, un servidor web.

Para terminar con esta parte vamos a ver un par de ejemplos de USDT (Userland Statically Defined Tracing). Los que habéis usado SystemTap o Dtrace ya sabréis de lo que estamos hablando. Para usar las USDT necesitamos que las aplicaciones tengan soporte para este tipo de prueba. Muchas de las más importantes lo tienen, aunque no siempre están compiladas en las versiones "normales" que se instalan en las distintas distribuciones. Para ver qué tenemos disponible en un ejecutable podemos usar el script tplist. Sacando un extracto de este buen post de Brendan Gregg, tplist muestra lo siguiente:

# tplist -l /usr/local/mysql/bin/mysqld
/usr/local/mysql/bin/mysqld mysql:filesort__start
/usr/local/mysql/bin/mysqld mysql:filesort__done
/usr/local/mysql/bin/mysqld mysql:handler__rdlock__start
/usr/local/mysql/bin/mysqld mysql:handler__rdlock__done
/usr/local/mysql/bin/mysqld mysql:handler__unlock__done
/usr/local/mysql/bin/mysqld mysql:handler__unlock__start
/usr/local/mysql/bin/mysqld mysql:handler__wrlock__start
/usr/local/mysql/bin/mysqld mysql:handler__wrlock__done
/usr/local/mysql/bin/mysqld mysql:insert__row__start
/usr/local/mysql/bin/mysqld mysql:insert__row__done
/usr/local/mysql/bin/mysqld mysql:update__row__start
/usr/local/mysql/bin/mysqld mysql:update__row__done
/usr/local/mysql/bin/mysqld mysql:delete__row__start
/usr/local/mysql/bin/mysqld mysql:delete__row__done
/usr/local/mysql/bin/mysqld mysql:net__write__start
/usr/local/mysql/bin/mysqld mysql:net__write__done
...
/usr/local/mysql/bin/mysqld mysql:command__done
/usr/local/mysql/bin/mysqld mysql:query__start
/usr/local/mysql/bin/mysqld mysql:query__done
/usr/local/mysql/bin/mysqld mysql:update__start
...

Viendo las opciones, podemos usar query_start y query_end para sacar las consultas lentas. El script se llama dbslower (ejemplo dbslower):

...
# Uprobes mode
bpf = BPF(text=program)
bpf.attach_uprobe(name=args.path, sym=mysql_func_name, fn_name="query_start")
bpf.attach_uretprobe(name=args.path, sym=mysql_func_name, fn_name="query_end")
...

Y al final tendremos algo parecido a esto:

# dbslower mysql -m 0
Tracing database queries for pids 25776 slower than 0 ms...
TIME(s)        PID          MS QUERY
6.003720       25776     2.363 /* mysql-connector-java-5.1.40 ( Revision: 402933ef52cad9aa82624e80acbea46e3a701ce6 ) */SELECT  @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_conn
6.599219       25776     0.068 SET NAMES latin1
6.613944       25776     0.057 SET character_set_results = NULL
6.645228       25776     0.059 SET autocommit=1
6.653798       25776     0.059 SET sql_mode='NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES'
6.682184       25776     2.526 select * from users where id = 0
6.767888       25776     0.288 select id from products where userid = 0
6.790642       25776     2.255 call getproduct(0)
6.809865       25776     0.218 call getproduct(1)
6.846878       25776     0.248 select * from users where id = 1
6.847623       25776     0.166 select id from products where userid = 1
6.867363 25776 0.244 call getproduct(2)

Hay muchas aplicaciones que permiten compilarse con soporte para USDT. En realidad, no solo aplicaciones; Python, PHP, Ruby, Java o Node, por ejemplo, también nos permiten ver dónde se está atascando nuestro código.

Vamos terminando con algo un poco más didáctico que práctico.

Imaginemos que tenemos unos cuantos volúmenes NFS en una máquina y que queremos saber qué está pasando. La primera opción que usaríamos la mayoría: nfsiostat. Es una buena aplicación, basada en deltas, como tantas otras, y que nos permite saber que en x tiempo se han servido z bytes en un determinado punto de montaje. Hasta aquí todo bien.

El problema con este tipo de aplicaciones, entre otros, es que no siempre capturan bien las distribuciones bimodales; aquellas en las que el acceso es correcto la mayoría del tiempo pero, puntualmente, se dan picos de latencia más altos. Estamos hablando de un servidor web que funciona bien "casi siempre". Estas distribuciones bimodales (de acceso a disco, carga de CPU, ...) son las que hacen que la percepción de un servicio sea desastrosa, y no siempre son fáciles de tratar.

Analizar el rendimiento NFS a fondo no es para nada trivial. Incluso centrándonos solo en la parte cliente, tenemos que vigilar la red, RPC, Caches NFS, bloqueos, .... Al final, salvo que tengáis tiempo y conocimientos suficientes para hacer algo completo vía BPF, lo normal, creo, sería empezar monitorizando a nivel VFS. Para esto hay varios scripts ya hechos en el repositorio de BCC. Por ejemplo, fileslower:

root@bpf-bcc:/usr/share/bcc/tools# python fileslower 0
Tracing sync read/writes slower than 0 ms
TIME(s)  COMM           TID    D BYTES   LAT(ms) FILENAME
4.089    bash           869    W 12         0.04 prueba5.txt

Con este tipo de herramientas tampoco tendremos los detalles de los que hemos hablado (red, RPC, ...), pero sí podremos, al menos, detectar anomalías en rutas concretas y distribuciones bimodales. TIP: BPF tiene una estructura para generar histogramas, que son algo más útiles con este tipo de distribución de datos.

Vamos a terminar viendo algunos scripts más y, de paso, damos un repaso a lo que hace el Kernel cuando hacemos algunas operaciones en sistemas de ficheros NFS. No pretendo que os sean útiles, aunque lo son, por ejemplo para generar Flame Graphs.

Vamos a usar funccount un par de veces. ¿Qué se ejecuta en el Kernel que empiece por nfs_ cuando se monta un volumen de este tipo?

# python funccount -i 1  'nfs_*'
FUNC                                    COUNT
nfs_fscache_get_client_cookie               1
nfs_alloc_client                            1
nfs_show_mount_options                      1
nfs_show_path                               1
nfs_create_server                           1
nfs_mount                                   1
nfs_fs_mount                                1
nfs_show_options                            1
nfs_server_insert_lists                     1
nfs_alloc_fhandle                           1
nfs_fscache_init_inode                      1
nfs_path                                    1
nfs_try_mount                               1
nfs_setsecurity                             1
nfs_init_locked                             1
nfs_init_server                             1
nfs_set_super                               1
nfs_init_server_rpcclient                   1
nfs_parse_mount_options                     1
nfs_probe_fsinfo                            1
nfs_fhget                                   1
nfs_get_client                              1
nfs_fs_mount_common                         1
nfs_show_devname                            1
nfs_create_rpc_client                       1
nfs_alloc_inode                             1
nfs_init_timeout_values                     1
nfs_set_sb_security                         1
nfs_start_lockd                             1
nfs_verify_server_address                   1
nfs_alloc_server                            1
nfs_init_server_aclclient                   1
nfs_init_client                             1
nfs_request_mount.constprop.19              1
nfs_fill_super                              1
nfs_get_root                                1
nfs_get_option_ul                           2
nfs_alloc_fattr                             2
nfs_fattr_init                              5

¿Y cuando escribimos algo?

FUNC                                    COUNT
nfs_writeback_result                        1
nfs_put_lock_context                        1
nfs_file_clear_open_context                 1
nfs_lookup                                  1
nfs_file_set_open_context                   1
nfs_close_context                           1
nfs_unlock_and_release_request              1
nfs_instantiate                             1
nfs_start_io_write                          1
nfs_dentry_delete                           1
nfs_writehdr_free                           1
nfs_generic_pgio                            1
nfs_file_write                              1
nfs_alloc_fhandle                           1
nfs_post_op_update_inode_force_wcc_locked        1
nfs_fscache_init_inode                      1
nfs_pageio_add_request                      1
nfs_end_page_writeback                      1
nfs_writepages                              1
nfs_page_group_clear_bits                   1
nfs_initiate_pgio                           1
nfs_write_begin                             1
nfs_pgio_prepare                            1
nfs_flush_incompatible                      1
nfs_pageio_complete_mirror                  1
nfs_sb_active                               1
nfs_writehdr_alloc                          1
nfs_init_locked                             1
nfs_initiate_write                          1
nfs_generic_pg_pgios                        1
nfs_file_release                            1
nfs_refresh_inode                           1
nfs_pageio_init_write                       1
nfs_pgio_data_destroy                       1
nfs_fhget                                   1
nfs_inode_remove_request                    1
nfs_create_request                          1
nfs_free_request                            1
nfs_end_io_write                            1
nfs_open                                    1
nfs_create                                  1
nfs_pageio_init                             1
nfs_pgio_result                             1
nfs_writepages_callback                     1
nfs_writeback_update_inode                  1
nfs_do_writepage                            1
nfs_key_timeout_notify                      1
nfs_alloc_inode                             1
nfs_writeback_done                          1
nfs_write_completion                        1
nfs_pageio_complete                         1
nfs_pgio_release                            1
nfs_lock_and_join_requests                  1
nfs_page_group_destroy                      1
nfs_fscache_open_file                       1
nfs_pageio_doio                             1
nfs_pgio_header_free                        1
nfs_generic_pg_test                         1
nfs_write_end                               1
nfs_post_op_update_inode                    1
nfs_updatepage                              1
nfs_pageio_cond_complete                    1
nfs_get_lock_context                        1
nfs_inode_attach_open_context               1
nfs_file_open                               1
nfs_fattr_set_barrier                       1
nfs_init_cinfo                              1
nfs_pgheader_init                           1
nfs_create_request.part.13                  1
nfs_sb_deactive                             1
nfs_post_op_update_inode_locked             2
nfs_commit_inode                            2
nfs_refresh_inode.part.18                   2
nfs_scan_commit                             2
nfs_commit_end                              2
nfs_setsecurity                             2
nfs_release_request                         2
nfs_page_find_head_request_locked           2
nfs_reqs_to_commit                          2
nfs_unlock_request                          2
nfs_ctx_key_to_expire                       2
nfs_file_fsync                              2
nfs_file_flush                              2
nfs_page_group_sync_on_bit                  3
nfs_revalidate_inode_rcu                    3
nfs_alloc_fattr                             3
nfs_revalidate_inode                        3
nfs_do_access                               3
nfs_update_inode                            4
nfs_permission                              4
nfs_init_cinfo_from_inode                   4
nfs_refresh_inode_locked                    4
nfs_file_has_buffered_writers               4
nfs_page_group_lock                         5
nfs_fattr_init                              5
nfs_page_group_unlock                       5
nfs_pgio_current_mirror                     6
nfs_set_cache_invalid                       8
nfs_attribute_cache_expired                10

También tenemos scripts para ver la pila, por ejemplo cuando se ejecuten nfs_file_write y nfs_write_end:

# python stacksnoop nfs_file_write -p 1080
TIME(s)            FUNCTION
0.556759834        nfs_file_write
    nfs_file_write
    new_sync_write
    vfs_write
    sys_write
    system_call_fast_compare_end


#python stacksnoop nfs_write_end -p 1080
TIME(s)            FUNCTION
1.933541059        nfs_write_end
    nfs_write_end
    generic_perform_write
    nfs_file_write
    new_sync_write
    vfs_write
    sys_write
    system_call_fast_compare_end

No quiero terminar sin que veamos el script trace, una especie de navaja suiza que vale para casi todo, com podéis ver en los ejemplos trace. Sigamos viendo más información sobre las escrituras en NFS. En una terminal voy a ejecutar esto:

while true
do
  echo "hola" >> /mnt/prueba.txt
  sleep 2
done

Y en otra un par de llamadas a trace:

# python trace -p 1647 'r:c:write ((int)retval > 0) "write ok: %d", retval' -T
TIME     PID    TID    COMM         FUNC             -
21:28:15 1647   1647   bash         write            write ok: 5
21:28:17 1647   1647   bash         write            write ok: 5

# python trace -p 1647 'sys_write "written %d file", arg1'
PID    TID    COMM         FUNC             -
1647   1647   bash         sys_write        written 1 file
1647   1647   bash         sys_write        written 1 file

Y ya está. No merece la pena seguir con más ejemplos, porque todo está razonablemente bien documentado, como habéis visto. Me he dejado muchos scripts, de todo tipo, pero seguro que os habéis hecho una idea.

Ojo! Que no haya dicho ni pio sobre XDP no significa que no sea interesante. Las posibilidades y el rendimiento de los desarrollos que está haciendo la gente (firewalls para contenedores, balanceadores de carga, ...) son muy prometedores, y seguro que van a llegar muy lejos. Quién sabe si será el tema del próximo post.


Monitorización de aplicaciones con sysdig

mié, 23 nov 2016 by Foron

Historicamente, uno de los argumentos más importantes de la comunidad Solaris en relación a la, no sé si decirlo así, madurez de Linux para entornos profesionales, ha sido la falta de instrumentalización para la monitorización del sistema.

En realidad, no faltaba razón en este argumento, ya que los primeros esfuerzos, por ejemplo de la mano de Systemtap, no conseguían llegar a lo que ofrecía el fantástico Dtrace en este tipo de entornos. A pesar de haber pasado ya varios años, no creo que ninguna de estas aplicaciones haya llegado a un público masivo (en el ámbito empresarial, claro).

Sin embargo, gracias al trabajo de mucha gente, estos últimos meses están siendo espectaculares para dotar a Linux, por fin, de herramientas capaces de igualar a Solaris. De hecho, alguna de las cabezas pensantes detrás de Dtrace, como Brendan Gregg, ahora trabajando en entornos Linux, ha venido a decir que ha sido como si, después de haber estado esperando al autobús, de repente hubiesen llegado dos. Os recomiendo esta lectura, con algo de contexto sobre la evolución de estas nuevas herramientas.

Hoy en día, como decía, tenemos varias alternativas. Personalmente, estoy interesado en dos: a) eBPF, o ya últimamente BPF, a secas, y b) Sysdig.

Con BPF se está dotando al Kernel Linux de toda la instrumentalización necesaria para inspeccionar al detalle el funcionamiento del sistema. A partir de ahí, un toolkit como BCC hace uso de todas estas nuevas estructuras para facilitar la manipulación de estos datos a través de un interfaz Python o Lua. Echad un vistado a la web. Los ejemplos son particularmente interesantes.

El soporte para BPF está integrado en los Kernels estándar recientes. Es algo en plena evolución, así que, si queréis probarlo, os recomiendo que no uséis nada inferior a 4.4, aunque ya haya cosas desde antes. En realidad, la cosa va tan rápido que, ya puestos, lo mejor es que probéis con 4.9 para ver lo último de lo último que se ha incluido.

Parece claro que se tienen muchas espectativas puestas en BPF. Hay varios proyectos importantes que ya se están planteando su uso. SystemTap, por ejemplo, está empezando a implementar un backend bajo BPF. Por otro lado, y bajo el mismo paraguas de BPF, se están desarrollando nuevas tecnologías, como XDP, que prometen una serie de ventajas que ya se están empezando a contemplar en el mundo de las redes software o los contenedores. Si queréis leer algo sobre esto, aquí tenéis un enlace.

La segunda alternativa de la que os hablaba, Sysdig, aunque para el usuario final que solo quiere monitorizar sus sistemas tenga, por así decirlo y cogido con alguna pinza, el mismo objetivo que BPF, lo hace de una manera diferente. Instrumentaliza el Kernel y ofrece un backend de calidad, pero delega gran parte del trabajo a filtros y a pequeños scripts, que llaman chisels (en Lua), que se encargan del trabajo desde el punto de vista del usuario.

En este momento, si dejáis de leer este post e investigáis por vuestra cuenta durante una hora, seguramente lleguéis a la conclusión de que BPF es realmente potente, pero que cuesta empezar (hay mucho hecho ya bajo el paraguas de iovisor, y cada poco sale un nuevo script). Por otro lado, es probable que en esa misma hora lleguéis a entender de qué va Sysdig, y que aunque no sea tan "amplio" como BPF, en realidad es más que suficiente para muchos de los problemas que habitualmente tiene el usuario de a pie. Ojo, que no estoy diciendo que Sysdig sea mejor que BPF, ni remotamente. Sacad vuestras propias conclusiones, pero leed sobre ambos y probadlos antes.

Tanto BPF como Sysdig dan para muchos posts. Os recomiendo leer el blog de Brendan Gregg, la documentación y los ejemplos de github de iovisor, y el blog y la web de Sysdig para ir calentando.

Mi idea original para el artículo era usar Sysdig en algún script real, pero eso lo haría mucho más denso, y he preferido limitarlo a algunas notas de lo que se puede hacer, aunque lo disfrazaré de ejemplo real.

Imaginad que tenéis un script que procesa un fichero de logs. En función de la expresión regular va a una u otra rama de código y, al final, inserta los resultados en mysql. En un entorno real, seguramente paralelizaríamos el script para aprovechar todos los cores, quizá usando zeromq para el paso de mensajes, y quizá usando el patrón que algunos llaman pipeline. Los entornos paralelos suelen complicar la monitorización.

Vamos a suponer la locura (irónico) de que no tenemos tiempo para la optimización o el análisis de ningún script, mucho menos si es cosa de horas, y todavía menos si el mencionado script no funciona rematadamente mal.

Y aquí es cuando alguien se levanta y dice: "Tanto rollo para algo que se puede solucionar con las trazas de toda la vida, (inicio = time.time(); fin = time.time(); dif = fin - inicio) ". No seré yo el que diga que este tipo de trazas no funcionen, aunque estaremos de acuerdo en que son "limitadas". Sirven para decir que algo va lento, pero no el motivo; aparte del tiempo que lleva procesar, digamos, 80 millones de lineas de log multiplicadas por tantos "ifs" como tenga el código, que además se ejecutan en procesos independientes. Es viable, por supuesto, pero mejorable.

Afortunadamete, ya habéis dedicado una hora a mirar tanto Sysdig como BPF/BCC y, claro, habréis llegado a la conclusión de que cualquiera de las dos os pueden servir. Veamos qué podemos hacer con Sysdig.

Repasemos: Una vez instalado Sysdig (os lo dejo a vosotros), se carga un módulo de Kernel que, simplificando un poco, va a ir recogiendo, eficientemente, los datos que se vayan generando (llamadas al sistema, IO, ...), de tal manera que luego se puedan aplicar filtros y chisels que nos den la información que necesitemos.

Además, tenemos suerte, porque una de las últimas funcionalidades que se han añadido a Sysdig consiste en algo tan sencillo como marcar el inicio y el fin de un bloque de código, y usar después estas marcas para el análisis. Imaginad que tenéis la capacidad de saber fácilmente la distribución del tiempo que necesita un "if" que incluye algunas operaciones sobre una base de datos; y que además podéis saber sin nada de esfuerzo el contenido íntegro del "select" que se mandó a la base de datos, o si falló la conexión o la resolución del nombre de la máquina bbdd para ese pequeño porcentaje de bloques lentos.

Y todavía es mejor, porque para hacer esto de lo que os estoy hablando solo hay que escribir una cadena concreta en /dev/null. Es previsible que esto será muy fácil, sea cual sea el lenguaje que estéis usando. Mirad estos ejemplos, sacados directamente de la web de sysdig.

echo ">:p:mysql::" > /dev/null
... código a analizar ...
echo "<:p:mysql::" > /dev/null

Y así de fácil. Con > y < definimos el comienzo y el final del bloque, con :p: pedimos que se genere un identificador automáticamente a partir del pid del proceso (hay más opciones), y usamos mysql como tag para identificar el span (que es como se llama todo esto, tracer/span).

Pero podemos ir un poco más lejos, y usar cadenas como las siguientes:

echo ">:p:mysql.select::" > /dev/null
echo ">:p:mysql.update::" > /dev/null
echo ">:p:mysql.select:query=from tabla1:" > /dev/null
echo ">:p:mysql.update:query=tabla1:" > /dev/null

Como veis, podemos anidar tags, o incluso añadir argumentos que den más pistas sobre lo que hace cada bloque. Esto es muy útil para saber la iteración exacta dentro de un for en la que ha ocurrido un problema concreto, o el tipo de select que ha generado cierto error, por decir un par de casos.

Volviendo a lo nuestro, recordad, queremos tener controlado un script python que escribe en una base de datos, que usa zeromq, y que se basa en expresiones regulares para hacer una cosa u otra. Sin pensar mucho, tendríamos una estructura de código parecida a esta:

fsysdig = open("/dev/null/", "w")

# Abrimos fichero log, creamos procesos, ...

for linea in fsysdig:
  fsysdig.write(">:p:zmq::\n")
  fsysdig.flush()
  # Preparamos los datos, y mandamos al socket push de ZMQ
  # Este socket se bloquea al llegar al tope de memoria configurado
  # ...
  socketzmq.send_multipart(["LOG",linea])
  # ...
  # Mas actividad para este span
  fsysdig.write("<:p:zmq::\n")
  fsysdig.flush()

En otros procesos tendremos la parte de la gestión de las expresiones regulares

fsysdig = open("/dev/null/", "w")

#
# Leeriamos del socket push via un socket pull de ZMQ
# ...
#

while seguirprocesando:
  # Hacemos match de una expresion regular
  # Si se cumple, hacemos ciertas operaciones
  # ...
  if matchregexp1:
    fsysdig.write(">:p:regexp:re=regexp1:\n")
    fsysdig.flush()
    # Trabajo con la regexp1
    # ...
    # Enviamos el dato al proceso mysql via ZMQ
    # ...
    fsysdig.write("<:p:regexp::\n")
    fsysdig.flush()

  if matchregexp2:
    fsysdig.write(">:p:regexp:re=regexp2:\n")
    fsysdig.flush()
    # Trabajo con la regexp2
    # ...
    # Y enviamos el dato al proceso mysql via ZMQ
    # ...
    fsysdig.write("<:p:regexp::\n")
    fsysdig.flush()
  #
  # Hariamos algo parecido con el resto ...
  #

Ya os hacéis una idea. Como veis, estamos añadiendo argumentos al tag regexp para identificar los bloques.

Por último, otro proceso haría el trabajo contra mysql.

fsysdig = open("/dev/null/", "w")

while seguirprocesando:
  #
  # Leeriamos del socket push via ZMQ, agrupariamos, operaciones, ...
  #
    try:
      fsysdig.write(">:p:mysql:st=update:\n")
      fsysdig.flush()
      # preparariamos la operacion mysql y el resto del trabajo para este span...
      cur.execute('''insert into ...''')
      # ...
    except (MySQLdb.MySQLError, TypeError) as e:
      print "Mysql: ERROR: Al ejecutar comando mysql " + str(e)
      sys.stdout.flush()
    finally:
      # ...
      fsysdig.write("<:p:mysql::\n")
      fsysdig.flush()

Como veis, también hemos creados argumentos para identificar bloques.

Este es el tipo de código que vamos a ejecutar. Antes de eso, vamos a poner en marcha la captura de sysdig (se puede lanzar en cualquier momento).

sysdig -C 500 -s 512 -w volcado_span.scap

Básicamente estamos creando ficheros independientes de 500MB, y estamos capturando 512 bytes de bufer de IO.

Una vez tengamos Sysdig lanzado dejamos el script funcionando un rato. Tendremos varios ficheros volcado_span.scap[0-9]+. Empecemos el análisis!

Una de las utilidades principales de Sysdig es un interfaz ncurses que permite ejecutar chisels fácilmente. Se llama csysdig. En nuestro caso, vamos a leer uno de los volcados para simplificar el proceso, pero tened en cuenta que todo esto se puede hacer sobre una captura en tiempo real, sin el parámetro -r

csysdig -r volcado_span.scap8

En este listado, F2 -> Traces Summary, y nos dará el resumen de spans que se han generado.

Sumario spans

Hagamos algo más interesante. Uno de los chisels más visuales que ha escrito la gente de Sysdig se llama "spectrogram", y se utiliza para ver la distribución de las latencias de ciertos eventos. Csysdig integra una versión que muestra la distribución para los spans, como una unidad. Os dejo que la veáis vosotros (hay videos en los tutoriales de la web de Sysdig). Aquí vamos a ser un poco más brutos y vamos a mostrarla para todos los eventos que se generan dentro de los bloques con el tag "regexp":

sysdig -r volcado_span.scap8 -c spectrogram 'evtin.span.p.tag[0]=regexp'

De donde sacaríamos lo siguiente:

Spectrogram regexp

Aunque lo que os muestro no es demasiado práctico (seguramente sea más interesante empezar por spans en bloque), imaginad que tenéis accesos a red o llamadas más costosas, y que tenéis mucho rojo hacia la derecha (muchos eventos y muy lentos). Esos serían, quizá, los eventos más interesantes a analizar:

sysdig -r volcado_span.scap8 -c spectrogram 'evtin.span.p.tag[0]=regexp and evt.latency > 100000'

Como veis, estamos aplicando filtros para limitar lo que vemos:

Spectrogram regexp lentas

Este tipo de imágenes me parecen interesantes para ver si hay algún tipo de anomalía o algo que no nos parezca razonable; aunque en un caso real antes o después dejaríamos de usar los chisel visuales y pasaríamos a ver los eventos concretos que están dando guerra. De hecho, la vista spectrogram de csysdig permite elegir con el ratón partes de la imágen para pasar a modo texto.

Y esto es, para mí, de lo mejor de Sysdig: Podemos limitarnos a grandes sumarios como los que hemos visto hasta ahora, o a ver lo que está ocurriendo a nivel de llamada a sistema. Además, aunque en este artículo nos hemos centrado en un análisis "a posteriori", en la práctica podemos lanzar csysdig en tiempo real y tener integradas en un mismo interfaz todas las funcionalidades, mejoradas, que dan comandos como htop o netstat, por citar un par.

Depende del caso de uso de cada uno. Yo, por ejemplo, en el día a día uso Sysdig sobre todo para ver el tráfico entre sockets. Por ejemplo, imaginad que tenéis algún tipo de middleware que hace llamadas HTTP a un servicio externo en función de las peticiones HTTP que recibe. Suponed que no logueáis esas peticiones, y que a veces fallan. En estos casos Sysdig es realmente útil.

El chisel echo_fds, por ejemplo, es muy interesante porque muestra todo el IO de los eventos que cumplan el filtro que apliquemos. Además, lo colorea en función de si es de entrada o de salida. Por supuesto, se puede usar para HTTP, como he comentado, pero también con cualquier otro proceso que genere IO, como por ejemplo, mysqld:

sysdig  -r volcado_span.scap11 -c echo_fds 'proc.name=mysqld'

Nos hemos olvidado de los spans, como veis, y vamos directamente a los procesos mysqld. Sin acotar más, tendremos un churro similar al siguiente

.....
------ Read 4B from   127.0.0.1:52398->127.0.0.1:mysql (mysqld)
....
------ Read 87B from   127.0.0.1:52398->127.0.0.1:mysql (mysqld)
.insert into tabla(timestamp, dato1, dato2) values (1477905741, 'ejemplo1', 'ejemplo2')
------ Write 11B to   127.0.0.1:52398->127.0.0.1:mysql (mysqld)
......

Como veis, estamos logueando todo el tráfico SQL, como el insert que he dejado aquí. Creedme, este tipo de chisels, con filtros como evt.buffer contains son muy útiles para ver tráfico HTTP, cabeceras, respuestas o códigos de error, particularmente en entornos con muchos microservicios y similares.

En fin, no sé si os habéis hecho una idea de lo que se puede hacer con Sysdig. En realidad, no os he dicho nada del otro mundo; teneis mucha mas informacion en la web y el blog de Sysdig, por citar dos fuentes. En cualquier caso, la unica forma de coger soltura con esto es con el uso, asi que lo mejor que podéis hacer es probarlo.

En comparación a lo que hemos hecho, y aprovechando que estamos hablando de mysql, en este enlace tenéis el ejemplo de cómo se mostrarian las consultas lentas con BPF/BCC. Si seguís el texto del enlace, veréis que podéis usar lo que ya esta hecho (usando el script mysqld_query.py de los ejemplos de BCC, o que también podéis pedir pizza y café y llegar a muy bajo nivel gracias al uso que puede hacer BPF/BCC de la instrumentalización que ofrece mysql, antes principalmente para Dtrace, y ahora también para Linux. En todo caso, mejor si leéis el post (y el resto de la web) de Brendan Gregg para ir sacando más conclusiones.

read more

Enrutamiento para dummies

jue, 27 sep 2012 by Foron

Si hay algo sobre lo que no hubiese querido escribir nunca en este blog es sobre el enrutamiento básico en Linux. Hace 10 años quizá hubiese sido más interesante, pero no ahora. Aún así, en este mundo del botón y del siguiente siguiente no tengo nada claro que la gente sepa exactamente lo que hay debajo de un "route -n", así que vamos a ello. Eso sí, para dummies. De hecho, me voy a pasar de básico, con lo que escribiré cosas que en condiciones normales merecerían una discusión. En fin.

Empezamos con el viejo comando "route -n", tan simple como siempre:

  # route -n
  Kernel IP routing table
  Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
  0.0.0.0         10.213.208.1    0.0.0.0         UG    0      0        0 eth0
  10.213.208.0    0.0.0.0         255.255.240.0   U     0      0        0 eth0
  192.168.10.0    0.0.0.0         255.255.255.0   U     0      0        0 eth1
  192.168.11.0    0.0.0.0         255.255.255.0   U     0      0        0 eth1

Lo normal cuando usamos la combinación route/ifconfig en la mayoría de las distribuciones, una puerta de enlace, una red para llegar a esa puerta de enlace a través de un dispositivo, y luego, en este caso, nuestras redes locales.

¿No hay nada más?

Pues sí, hay mucho más, claro. Esto no es más que una mínima porción de la tabla de enrutamiento de vuestro kernel favorito. Vamos a verlo pasando a la utilidad "ip", la pobre, que lleva tanto tiempo existiendo, pero que tan poco se usa (solo comparable al uso eterno de los aliases de IPs, pero esta es otra historia).

  # ip route ls
  default via 10.213.208.1 dev eth0
  10.213.208.0/20 dev eth0  proto kernel  scope link  src 10.213.218.162
  192.168.10.0/24 dev eth1  proto kernel  scope link  src 192.168.10.1
  192.168.11.0/24 dev eth1  proto kernel  scope link  src 192.168.11.1

¿Todo este rollo para ver lo mismo con un formato diferente?

Sí, porque estamos viendo, una vez más, solo una parte de la tabla de enrutamiento. ¡Hola "ip rule"!

  # ip rule ls
  0:      from all lookup local
  32766:  from all lookup main
  32767:  from all lookup default

Y ahora, sorpresa:

  # ip route ls table default
  _vacio_
  # ip route ls table main
  default via 10.213.208.1 dev eth0
  10.213.208.0/20 dev eth0  proto kernel  scope link  src 10.213.218.162
  192.168.10.0/24 dev eth1  proto kernel  scope link  src 192.168.10.1
  192.168.11.0/24 dev eth1  proto kernel  scope link  src 192.168.11.1
  # ip route ls table local
  broadcast 10.213.208.0 dev eth0  proto kernel  scope link  src 10.213.218.162
  local 10.213.218.162 dev eth0  proto kernel  scope host  src 10.213.218.162
  broadcast 10.213.223.255 dev eth0  proto kernel  scope link  src 10.213.218.162
  broadcast 127.0.0.0 dev lo  proto kernel  scope link  src 127.0.0.1
  local 127.0.0.0/8 dev lo  proto kernel  scope host  src 127.0.0.1
  local 127.0.0.1 dev lo  proto kernel  scope host  src 127.0.0.1
  broadcast 127.255.255.255 dev lo  proto kernel  scope link  src 127.0.0.1
  broadcast 192.168.10.0 dev eth1  proto kernel  scope link  src 192.168.10.1
  local 192.168.10.1 dev eth1  proto kernel  scope host  src 192.168.10.1
  broadcast 192.168.10.255 dev eth1  proto kernel  scope link  src 192.168.10.1
  broadcast 192.168.11.0 dev eth1  proto kernel  scope link  src 192.168.11.1
  local 192.168.11.1 dev eth1  proto kernel  scope host  src 192.168.11.1
  broadcast 192.168.11.255 dev eth1  proto kernel  scope link  src 192.168.11.1

Vaya sorpresa... Lo que vemos con un "route -n" es en realidad la tabla "main", que además, por ese 32766, parece tener menos prioridad que esa tabla "local" tan curiosa. Fácil de leer, ¿Verdad? Los broadcast los conocemos todos pero, ¿Y las rutas de tipo local? Sacado literalmente del manual (Sí, todo esto está en el manual de ip route!!!): "the destinations are assigned to this host. The packets are looped back and delivered locally". Y con esto hemos terminado, solo nos queda saber que "proto kernel" es la configuración más normal si no usamos software de enrutamiento (quagga, por ejemplo), y que "scope link" es para rutas broadcast y unicast mientras que "scope host" es para las locales.

Revisad los manuales de "ip rule" e "ip route", por favor, y entended cada entrada de estas tablas y reglas.

Ya que estamos, vamos a jugar un poco con todo esto que hemos visto, aunque seguimos en "modo sencillo" y no nos vamos a complicar demasiado. Solo unas ideas.

Nota: No hagáis caso a las IPs que uso a partir de aquí. Intentaré mantenerlas coherentes, pero me las estoy inventando sobre la marcha.

Tenemos reglas en "ip rule", tenemos tablas de enrutamiento, ... ¿Apostamos a que todo esto es modificable/configurable? ¡Por supuesto!

Vamos a vuestra distribución Debian favorita, y busquemos el fichero "/etc/iproute2/rt_tables"

  # cat /etc/iproute2/rt_tables
  #
  # reserved values
  #
  255     local
  254     main
  253     default
  0       unspec
  #
  # local
  #
  #1      inr.ruhep

  1001 proveedor1
  1002 proveedor2

No, en vuestros ficheros no van a estar las líneas "proveedor1" y "proveedor2". Las he añadido yo, alegremente. Donde estoy escribiendo este post no hay múltiples lineas de acceso a Internet, pero me voy a inventar, como ejemplo, que en mi equipo hay dos ADSL de proveedores diferentes. Uno me ha asignado la IP 192.0.2.33/24, con puerta de enlace 192.0.2.1, y el segundo 198.51.100.33/24, con gateway 198.51.100.1.

Como ya sabemos todo sobre enrutamiento, queremos mandar a los comerciales a través del primer proveedor, y a los técnicos a través del segundo. Supongamos que los comerciales están todos en la subred "172.16.0.0/24", y los técnicos en "172.16.1.0/24".

¡Juguemos con ip rule!

  # ip rule add from 172.16.0.0/24 table proveedor1
  # ip rule add from 172.16.1.0/24 table proveedor2
  # ip rule ls
  0:      from all lookup local
  32764:  from 172.16.1.0/24 lookup proveedor2
  32765:  from 172.16.0.0/24 lookup proveedor1
  32766:  from all lookup main
  32767:  from all lookup default

Efectivamente, hemos separado el tráfico en dos tablas, por ahora vacías. Es el turno de ip route:

  # ip route add 172.16.0.0/16 dev eth0 src 172.16.0.1 table proveedor1
  # ip route add 192.0.2.0/24 dev eth1 src 192.0.2.33 table proveedor1
  # ip route add default via 192.0.2.1 table proveedor1

  # ip route add 172.16.0.0/16 dev eth0 src 172.16.0.1 table proveedor2
  # ip route add 198.51.100.0/24 dev eth2 src 198.51.100.33 table proveedor2
  # ip route add default via 198.51.100.1 table proveedor2

¿Veis lo que hemos hecho? Hemos asignado dos puertas de enlace por defecto diferentes, en base al origen, por lo que todo lo que venga desde 172.16.0.0/24 irá por 192.0.2.1, y lo originado en 172.16.1.0/24 por 198.51.100.1. Por si fuera poco, el tráfico que no entre en ninguna de estas dos subredes accederá a la tabla main (from all lookup main), y con ello usará la puerta de enlace por defecto de toda la vida, esa que pensábamos que era única.

Y ya está, aquí lo dejo, aunque debo recordaros que esto no es una guía tipo copy/paste, ni remotamente.

Notas:

  • Como no podía ser de otra forma, el direccionamiento interno de este post no puede salir directamente a Internet. Hay que hacer SNAT (o el masquerade de toda la vida) en iptables. Lo normal es que conntrack haga magia y sepa dónde mandar vuestro tráfico, pero también es posible que se tenga que jugar más a fondo con ello.
  • Las entradas que añaden rutas a las tablas están simplificadas. Sería deseable completarlas, por ejemplo para evitar avisos de ICMP sobre mejores rutas si quisiésemos mandar tráfico entre redes. Lo dicho, no es más que un ejemplo.
  • En función de las configuraciones, interfaces, firewalls, ... puede ser posible que se tenga que cambiar algún parámetro de kernel, como por ejemplo, lo relacionado con rp_filter (Google es vuestro amigo). Por supuesto, ni que decir ip_forward.
  • Una vez más, esto es un mínimo ejemplo de lo mucho que se puede hacer. Las reglas, sin ir más lejos, pueden definirse por IP origen, destino, o incluso por marca de firewall, con lo que las posibilidades son enormes.
  • Os recomiendo completar lo visto en este post con todo lo que hay alrededor del enrutamiento en un kernel normal, con soporte Netfilter. Pista.
read more

Systemtap para detectar la actividad de ficheros de un proceso

lun, 18 jul 2011 by Foron
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.

read more

Monitorización del kernel con SystemTap II

sáb, 11 abr 2009 by Foron

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.

Systemtap

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, en su caso, la solución.

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.

read more