Hay muchas herramientas para depurar kernel y programas de espacio de usuario en Linux. La mayoría de ellos tienen un impacto en el rendimiento y no se pueden ejecutar fácilmente en entornos de producción. Hace unos años,
se desarrolló eBPF, que proporciona la capacidad de rastrear el núcleo y el espacio de usuario con una sobrecarga baja, sin necesidad de volver a compilar programas o cargar módulos de núcleo.
Ahora hay muchas herramientas que usan eBPF y en este artículo, explicaremos cómo escribir su propia herramienta de creación de perfiles utilizando la
biblioteca PythonBCC . Este artículo se basa en un problema real del entorno de producción. Le guiaremos a través de la resolución del problema y le mostraremos cómo se pueden usar las herramientas bcc existentes en algunos casos.
Ceph es lento
Se agregó una nueva plataforma a un grupo ceph. Después de migrar algunos datos a la plataforma, la latencia para las solicitudes de escritura fue mayor que en los otros servidores.
Esta plataforma tiene un nuevo dispositivo virtual de almacenamiento en caché, bcache, que no hemos usado en este clúster antes, y un nuevo núcleo, 4.15, que todavía no se usa en ningún otro lugar de este clúster. La raíz del problema podría estar en cualquier lugar, así que echemos un vistazo más profundo.
Investigando al anfitrión
Echemos un vistazo a lo que sucede dentro del proceso ceph-osd. Utilizamos la herramienta de rastreo
perf y
flamescope para construir gráficos de llamas:
Como podemos ver en el gráfico de llamas,
fdatasync () pasó mucho tiempo enviando bio en la función
generic_make_request () . Por lo tanto, la raíz de nuestro problema está en algún lugar fuera del ceph daemon. Puede ser un problema de kernel, bcache o disco. La salida de iostat mostró alta latencia para dispositivos bcache.
Otro hallazgo sospechoso es que el demonio systemd-udevd está consumiendo CPU; alrededor del 20% en múltiples CPU. Este es un comportamiento extraño, por lo que tenemos que averiguar qué está pasando. Dado que systemd-udevd funciona con uevents, tenemos que usar
udevadm monitor para averiguar si hay algún evento en el sistema. Después de verificar, vimos que se generaban muchos eventos de "cambio" para cada dispositivo de bloque en el sistema.
Esto es inusual, así que vamos a descubrir qué está causando que se envíen todos estos eventos.
Usando el kit de herramientas BCC
Como ya sabemos, el kernel (y ceph daemon) está pasando mucho tiempo realizando funciones
generic_make_requst () .
Midamos su latencia utilizando la
funclatency del
kit de herramientas BCC , solo para asegurarnos de que estamos en el camino correcto. Trazaremos el PID del ceph daemon (argumento -p) en intervalos de 1 segundo (-i) e imprimiremos la latencia en milisegundos (-m).
Esta función generalmente funciona muy rápido. Todo lo que hace es enviar la bioestructura a la cola del controlador del dispositivo.
Bcache es un dispositivo complejo; de hecho, consta de 3 dispositivos: un dispositivo de respaldo, que es un HDD lento en nuestro caso; un dispositivo de almacenamiento en caché, que es la partición de la unidad NVMe; y un dispositivo virtual bcache, que es utilizado por la aplicación. Sabemos que la presentación es lenta, pero ¿para qué dispositivo? Esto es algo que veremos más adelante.
Por ahora, sabemos que los eventos causan problemas en los demonios ceph y tenemos que encontrar el software que desencadena eventos. No es fácil encontrar la causa de que se generen eventos. Asumimos que es un software que solo se ejecuta periódicamente. Para ver qué se está ejecutando en el sistema, utilizamos
execsnoop del kit de herramientas BCC. Podemos ejecutarlo y redirigir
stdout a un archivo.
Por ejemplo:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Aquí no daremos la salida completa de execsnoop, pero una cadena interesante que encontramos allí fue:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/'
La tercera columna es el PPID del proceso. Verificamos qué era 5802 y vimos que es uno de nuestros hilos de daemon de monitoreo. Mirando más a fondo la configuración del sistema de monitoreo, encontramos un parámetro defectuoso. La temperatura del HBA se recuperaba cada 30 segundos, lo cual es muy frecuente. Después de cambiar el intervalo de verificación a un valor más apropiado, vimos que nuestra latencia ceph coincidía con las otras plataformas.
Pero todavía no sabemos por qué la latencia de bcache fue alta. Configuramos una plataforma de prueba con la misma configuración e intentamos reproducir el problema con fio en el dispositivo bcache mientras simultáneamente activamos udev con el comando de activación udevadm.
Escribir herramientas basadas en BCC
Lo que haremos aquí es escribir una herramienta simple que rastree las llamadas más lentas generic_make_request () e imprima el nombre del disco para el que se solicitó la función.
El plan es simple:
- Registre kprobe en generic_make_request () :
- Guarde el nombre del disco disponible desde el argumento de la función
- Guardar la marca de tiempo actual
- Registre kretprobe en la declaración de devolución generic_make_request () :
- Recuperar la marca de tiempo actual
- Busque marcas de tiempo guardadas previamente y compárelas con las actuales
- Si el resultado es más alto que el umbral, busque los nombres de disco previamente guardados e imprímalos en el terminal con información adicional
Kprobes y
kretprobes usan puntos de interrupción para cambiar el código de una función en tiempo de ejecución. Puede encontrar
documentación y un buen
artículo sobre esto. Si observa el código de las diferentes
herramientas de BCC , verá que todas tienen una estructura idéntica. Omitiremos el análisis de argumentos y nos centraremos en el programa BPF.
El texto de nuestro programa se definirá en python de la siguiente manera:
bpf_text = “””
Los programas BPF usan
hashmaps para compartir datos entre diferentes funciones. Usaremos PID como una clave y una estructura autodefinida como un valor.
struct data_t { u64 pid; u64 ts; char comm[TASK_COMM_LEN]; u64 lat; char disk[DISK_NAME_LEN]; }; BPF_HASH(p, u64, struct data_t); BPF_PERF_OUTPUT(events);
Aquí registramos un hashmap llamado
p con un tipo de clave
u64 y un tipo de valor
struct data_t . Este mapa es accesible desde el contexto de nuestro programa BPF. La macro
BPF_PERF_OUTPUT registra otro mapa llamado
eventos , que se utiliza para
enviar datos al espacio de usuario.
Al medir la latencia entre la llamada de función y su retorno o entre una llamada de función y otra, debe asegurarse de que los datos que guardó y acceda más tarde se relacionan con el mismo contexto. En otras palabras, debe tener en cuenta cualquier otra ejecución paralela de la misma función. Es posible rastrear la latencia entre la llamada de función de un proceso y los retornos de la misma función de otro proceso, pero esto no nos ayuda. Un buen ejemplo es la
herramienta de biolatencia donde se utiliza la
solicitud de puntero a
estructura como clave de hashmap.
A continuación, tenemos que escribir un código que se ejecutará en las llamadas de función a través de un mecanismo kprobe:
void start(struct pt_regs *ctx, struct bio *bio) { u64 pid = bpf_get_current_pid_tgid(); struct data_t data = {}; u64 ts = bpf_ktime_get_ns(); data.pid = pid; data.ts = ts; bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name); p.update(&pid, &data); }
Aquí tenemos el primer
argumento generic_make_request () como el segundo argumento de nuestra función. Luego obtenemos el PID y la marca de tiempo actual en nanosegundos y lo escribimos en la
estructura recientemente asignada
data_t data . Obtenemos el nombre del disco de la
bioestructura , que se pasa a
generic_make_request () , y lo
guardamos en nuestros
datos . El último paso es agregar una entrada al hashmap que describimos anteriormente.
Esta función se ejecutará en
generic_make_request () devuelve:
void stop(struct pt_regs *ctx) { u64 pid = bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); struct data_t* data = p.lookup(&pid); if (data != 0 && data->ts > 0) { bpf_get_current_comm(&data->comm, sizeof(data->comm)); data->lat = (ts - data->ts)/1000; if (data->lat > MIN_US) { FACTOR data->pid >>= 32; events.perf_submit(ctx, data, sizeof(struct data_t)); } p.delete(&pid); } }
Obtenemos el PID y la marca de tiempo de la salida anterior y buscamos el hashmap para el valor donde
key == PID actual . Si se encuentra, obtenemos el nombre del proceso en ejecución y lo agregamos a la estructura de
datos . Lo que hacemos con
datos-> pid aquí nos da la identificación del grupo de subprocesos. La función anteriormente llamada
bpf_get_current_pid_tgid () devuelve el hilo GID y PID del proceso en el mismo valor de 64 bits.
No estamos interesados en la identificación de cada hilo, pero queremos saber el PID del hilo principal. Después de verificar que la latencia está por encima del umbral, enviamos nuestra estructura de
datos al espacio de usuario a través del mapa de
eventos , luego eliminamos la entrada de hashmap al final.
En nuestro script de Python, tenemos que reemplazar
MIN_US y
FACTOR de acuerdo con el umbral que queremos y la unidad de tiempo que queremos ver en nuestro resultado:
bpf_text = bpf_text.replace('MIN_US',str(min_usec)) if args.milliseconds: bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;') label = "msec" else: bpf_text = bpf_text.replace('FACTOR','') label = "usec"
Luego tenemos que preparar el programa BPF con una
macro BPF () y registrar sondas:
b = BPF(text=bpf_text) b.attach_kprobe(event="generic_make_request",fn_name="start") b.attach_kretprobe(event="generic_make_request",fn_name="stop")
También necesitamos definir la misma estructura que
struct data_t en nuestro script para leer los datos del programa BPF:
TASK_COMM_LEN = 16
El último paso es imprimir los datos que queremos:
def print_event(cpu, data, size): global start event = ct.cast(data, ct.POINTER(Data)).contents if start == 0: start = event.ts time_s = (float(event.ts - start)) / 1000000000 print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk)) b["events"].open_perf_buffer(print_event)
El script completo está disponible en
GitHub . Ejecutemos el script y activemos eventos udev mientras fio escribe en un dispositivo bcache:
Éxito! Ahora vemos que lo que parecía una latencia alta para bcache es realmente
una latencia
generica_make_request () para su dispositivo de respaldo.
Cavar en el núcleo
¿Qué se arrastra al enviar solicitudes? Vemos que se produjo un pico de latencia incluso antes de que comenzara la contabilidad de solicitudes. Esto podría verificarse fácilmente ejecutando iostat durante el problema o el
script BCC de biolatencia , que se basa en el inicio de la solicitud de contabilidad, por lo que ninguna herramienta mostrará el problema del disco.
Si echamos un vistazo a
generic_make_request () , vemos que hay dos funciones ejecutándose antes de que comience la contabilidad. El primero es
generic_make_request_checks () , que es liviano y verifica bio según la configuración del dispositivo, etc. El segundo es
blk_queue_enter () , que tiene una llamada
wait_event_interruptible () :
ret = wait_event_interruptible(q->mq_freeze_wq, (atomic_read(&q->mq_freeze_depth) == 0 && (preempt || !blk_queue_preempt_only(q))) || blk_queue_dying(q));
Aquí el núcleo espera hasta que la cola se descongela. Midamos la latencia de blk_queue_enter ():
~
Parece que estamos cerca. Las funciones utilizadas para congelar / descongelar la cola son
blk_mq_freeze_queue y
blk_mq_unfreeze_queue . Se usan para cambiar la configuración de la cola, lo que podría afectar las solicitudes de io que se encuentran actualmente en vuelo. Cuando se llama a
blk_mq_freeze_queue () ,
q-> mq_freeze_depth se incrementa en
blk_freeze_queue_start () . Después de eso, el kernel espera a que la cola esté vacía en
blk_mq_freeze_queue_wait () .
Este tiempo de espera es igual a la latencia del disco, porque el núcleo tiene que esperar a que finalicen todas las operaciones io. Cuando la cola está vacía, se pueden hacer cambios. El último paso es llamar a
blk_mq_unfreeze_queue () , lo que disminuye el contador
freeze_depth .
Ahora sabemos lo suficiente como para solucionar el problema. El comando de disparo udevadm cambia la configuración de los dispositivos de bloque. Esos ajustes se describen en las reglas de udev. Podemos averiguar qué configuraciones congelan la cola cambiándolas a través de sysfs o mirando el código fuente del kernel. Alternativamente, podemos
llamar a trace desde el kit de herramientas BCC para imprimir el kernel y las pilas de usuarios para cada llamada
blk_freeze_queue :
~
Las reglas de Udev no cambian con frecuencia, por lo que incluso asignar valores ya existentes a ciertos parámetros provoca un aumento en la latencia de envío para la aplicación. Por supuesto, generar eventos udev cuando no hay cambios en la configuración de un dispositivo (ningún dispositivo está conectado o desconectado) no es una buena práctica. Aún así, podemos evitar que el núcleo congele la cola si no hay razón para hacerlo.
Tres pequeños commits solucionan el problema.
Conclusión
eBPF es un instrumento altamente flexible y potente. En este artículo, analizamos solo un caso y demostramos un poco de lo que es capaz de hacer. Si está interesado en desarrollar herramientas basadas en BCC, debería echar un vistazo al
tutorial oficial , que describe sus conceptos fundamentales.
También hay otras herramientas interesantes basadas en eBPF disponibles para perfilar y depurar. Uno de ellos es
bpftrace , que le permite escribir en línea potentes y pequeños programas en un lenguaje parecido al awk. Otro es
ebpf_exporter , que puede recopilar métricas de baja resolución y alta resolución para su servidor prometheus con sus excelentes capacidades de visualización y alerta.