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.


Comments