В Linux Existen numerosas herramientas para depurar núcleos y aplicaciones. La mayoría de ellas afectan negativamente al rendimiento de las aplicaciones y no pueden utilizarse en entornos de producción.
Hace un par de años hubo - eBPF. Hace posible rastrear el kernel y las aplicaciones de usuario con poca sobrecarga y sin la necesidad de reconstruir programas y cargar módulos de terceros en el kernel.
Ya existen muchas utilidades de aplicaciones que utilizan eBPF y en este artículo veremos cómo escribir su propia utilidad de creación de perfiles basada en la biblioteca. . El artículo está basado en hechos reales. Iremos del problema a la solución para mostrar cómo se pueden utilizar las utilidades existentes en situaciones específicas.
Ceph es lento
Se agregó un nuevo host al clúster de Ceph. Después de migrar algunos de los datos, notamos que la velocidad de procesamiento de solicitudes de escritura era mucho menor que en otros servidores.
A diferencia de otras plataformas, este host utilizó bcache y el nuevo kernel Linux 4.15. Esta fue la primera vez que se utilizó aquí un host de esta configuración. Y en ese momento quedó claro que, en teoría, la raíz del problema podría ser cualquier cosa.
Investigando al anfitrión
Comencemos viendo lo que sucede dentro del proceso ceph-osd. Para esto usaremos и (más sobre el cual puedes leer ):
La imagen nos dice que la función fdatasync () Pasé mucho tiempo enviando una solicitud a funciones. solicitud_fabricante_genérica(). Esto significa que lo más probable es que la causa de los problemas esté en algún lugar fuera del propio demonio osd. Puede ser el kernel o los discos. La salida de iostat mostró una alta latencia en el procesamiento de solicitudes mediante discos bcache.
Al verificar el host, encontramos que el demonio systemd-udevd consume una gran cantidad de tiempo de CPU, alrededor del 20% en varios núcleos. Este es un comportamiento extraño, por lo que es necesario descubrir por qué. Dado que Systemd-udevd trabaja con uevents, decidimos analizarlos a través de monitor udevadm. Resulta que se generó una gran cantidad de eventos de cambio para cada dispositivo de bloque en el sistema. Esto es bastante inusual, por lo que tendremos que observar qué genera todos estos eventos.
Usando el kit de herramientas de BCC
Como ya hemos descubierto, el kernel (y el demonio ceph en la llamada al sistema) pasa mucho tiempo en solicitud_fabricante_genérica(). Intentemos medir la velocidad de esta función. EN Ya existe una utilidad maravillosa: funclatencia. Rastrearemos el demonio por su PID con un intervalo de 1 segundo entre salidas y generaremos el resultado en milisegundos.
Esta característica suele funcionar rápidamente. Todo lo que hace es pasar la solicitud a la cola del controlador del dispositivo.
Bcaché es un dispositivo complejo que en realidad consta de tres discos:
- dispositivo de respaldo (disco en caché), en este caso es un disco duro lento;
- dispositivo de almacenamiento en caché (disco de almacenamiento en caché), aquí esta es una partición del dispositivo NVMe;
- el dispositivo virtual bcache con el que se ejecuta la aplicación.
Sabemos que la transmisión de solicitudes es lenta, pero ¿para cuál de estos dispositivos? Nos ocuparemos de esto un poco más tarde.
Ahora sabemos que es probable que los uevents causen problemas. Encontrar qué causa exactamente su generación no es tan fácil. Supongamos que se trata de algún tipo de software que se inicia periódicamente. Veamos qué tipo de software se ejecuta en el sistema usando un script. ejecutivosnoop del mismo . Ejecutémoslo y enviemos el resultado a un archivo.
Por ejemplo, como este:
/usr/share/bcc/tools/execsnoop | tee ./execdump
No mostraremos el resultado completo de execsnoop aquí, pero una línea que nos interesaba era la siguiente:
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 (PID principal) del proceso. El proceso con PID 5802 resultó ser uno de los hilos de nuestro sistema de monitoreo. Al verificar la configuración del sistema de monitoreo, se encontraron parámetros erróneos. La temperatura del adaptador HBA se tomó cada 30 segundos, que es mucho más frecuente de lo necesario. Después de cambiar el intervalo de verificación a uno más largo, descubrimos que la latencia de procesamiento de solicitudes en este host ya no destacaba en comparación con otros hosts.
Pero todavía no está claro por qué el dispositivo bcache era tan lento. Preparamos una plataforma de prueba con una configuración idéntica e intentamos reproducir el problema ejecutando fio en bcache, ejecutando periódicamente udevadm trigger para generar uevents.
Escribir herramientas basadas en BCC
Intentemos escribir una utilidad sencilla para rastrear y mostrar las llamadas más lentas. solicitud_fabricante_genérica(). También nos interesa el nombre de la unidad para la que se llamó esta función.
El plan es sencillo:
- Registro sonda k en solicitud_fabricante_genérica():
- Guardamos el nombre del disco en la memoria, accesible a través del argumento de la función;
- Guardamos la marca de tiempo.
- Registro sonda kret para regresar de solicitud_fabricante_genérica():
- Obtenemos la marca de tiempo actual;
- Buscamos la marca de tiempo guardada y la comparamos con la actual;
- Si el resultado es mayor que el especificado, buscamos el nombre del disco guardado y lo mostramos en el terminal.
Ksondas и kretprobes utilice un mecanismo de punto de interrupción para cambiar el código de función sobre la marcha. Puedes leer и artículo sobre este tema. Si observa el código de varias utilidades en , entonces podrás ver que tienen una estructura idéntica. Entonces, en este artículo omitiremos el análisis de los argumentos del script y pasaremos al programa BPF en sí.
El texto eBPF dentro del script de Python se ve así:
bpf_text = “”” # Here will be the bpf program code “””
Para intercambiar datos entre funciones, los programas eBPF utilizan . Haremos lo mismo. Usaremos el PID del proceso como clave y definiremos la estructura como 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 una tabla hash llamada p, con tipo de clave u64 y un valor de tipo estructura datos_t. La tabla estará disponible en el contexto de nuestro programa BPF. La macro BPF_PERF_OUTPUT registra otra tabla llamada eventos, que se utiliza para en el espacio del usuario.
Al medir los retrasos entre llamar a una función y regresar de ella, o entre llamadas a diferentes funciones, debe tener en cuenta que los datos recibidos deben pertenecer al mismo contexto. En otras palabras, es necesario recordar el posible lanzamiento paralelo de funciones. Tenemos la capacidad de medir la latencia entre llamar a una función en el contexto de un proceso y regresar de esa función en el contexto de otro proceso, pero esto probablemente sea inútil. Un buen ejemplo aquí sería , donde la clave de la tabla hash se establece en un puntero a solicitud de estructura, que refleja una solicitud de disco.
A continuación, debemos escribir el código que se ejecutará cuando se llame a la función en estudio:
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í el primer argumento de la función llamada se sustituirá como segundo argumento. . Después de esto, obtenemos el PID del proceso en el contexto en el que estamos trabajando y la marca de tiempo actual en nanosegundos. Lo anotamos todo en un cuaderno recién seleccionado. estructura data_t datos. Obtenemos el nombre del disco de la estructura. bio, que se pasa al llamar solicitud_fabricante_genérica()y guardarlo en la misma estructura en. El último paso es agregar una entrada a la tabla hash mencionada anteriormente.
La siguiente función será llamada al regresar de solicitud_fabricante_genérica():
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);
}
}
Esta función es similar a la anterior: averiguamos el PID del proceso y la marca de tiempo, pero no asignamos memoria para la nueva estructura de datos. En su lugar, buscamos en la tabla hash una estructura ya existente usando la clave == PID actual. Si se encuentra la estructura, averiguamos el nombre del proceso en ejecución y se lo agregamos.
El cambio binario que usamos aquí es necesario para obtener el hilo GID. aquellos. PID del proceso principal que inició el hilo en cuyo contexto estamos trabajando. La función que llamamos devuelve tanto el GID del subproceso como su PID en un único valor de 64 bits.
Al enviar a la terminal, actualmente no estamos interesados en el hilo, pero sí en el proceso principal. Después de comparar el retraso resultante con un umbral dado, pasamos nuestra estructura en en el espacio de usuario a través de la tabla eventos, después de lo cual eliminamos la entrada de p.
En el script de Python que cargará este código, necesitamos reemplazar MIN_US y FACTOR con los umbrales de retraso y las unidades de tiempo, que pasaremos a través de los argumentos:
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"
Ahora necesitamos preparar el programa BPF a través de y registrar muestras:
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 tendremos que determinar estructura datos_t en nuestro script, de lo contrario no podremos leer nada:
TASK_COMM_LEN = 16 # linux/sched.h
DISK_NAME_LEN = 32 # linux/genhd.h
class Data(ct.Structure):
_fields_ = [("pid", ct.c_ulonglong),
("ts", ct.c_ulonglong),
("comm", ct.c_char * TASK_COMM_LEN),
("lat", ct.c_ulonglong),
("disk",ct.c_char * DISK_NAME_LEN)]
El último paso es enviar datos al terminal:
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)
# format output
start = 0
while 1:
try:
b.perf_buffer_poll()
except KeyboardInterrupt:
exit()
El guión en sí está disponible en . Intentemos ejecutarlo en una plataforma de prueba donde se ejecuta fio, escribiendo en bcache y llamando al monitor udevadm:
¡Finalmente! Ahora vemos que lo que parecía un dispositivo bcache bloqueado es en realidad una llamada bloqueada. solicitud_fabricante_genérica() para un disco en caché.
Profundiza en el núcleo
¿Qué es exactamente lo que se ralentiza durante la transmisión de la solicitud? Vemos que el retraso ocurre incluso antes del inicio de la contabilidad de solicitudes, es decir La contabilidad de una solicitud específica para generar más estadísticas sobre ella (/proc/diskstats o iostat) aún no ha comenzado. Esto se puede verificar fácilmente ejecutando iostat mientras se reproduce el problema, o , que se basa en el inicio y el final de la contabilidad de solicitudes. Ninguna de estas utilidades mostrará problemas para las solicitudes al disco en caché.
Si miramos la función solicitud_fabricante_genérica(), luego veremos que antes de que la solicitud comience a contabilizarse, se llaman dos funciones más. Primero - generic_make_request_checks(), realiza comprobaciones sobre la legitimidad de la solicitud con respecto a la configuración del disco. Segundo - , que tiene un interesante desafío :
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));
En él, el núcleo espera a que la cola se descongele. midamos el retraso blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end.
msecs : count distribution
0 -> 1 : 341 |****************************************|
msecs : count distribution
0 -> 1 : 316 |****************************************|
msecs : count distribution
0 -> 1 : 255 |****************************************|
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 1 | |
Parece que estamos cerca de una solución. Las funciones utilizadas para congelar/descongelar una cola son и . Se utilizan cuando es necesario cambiar la configuración de la cola de solicitudes, lo que es potencialmente peligroso para las solicitudes de esta cola. al llamar blk_mq_freeze_queue() функцией el contador se incrementa q->mq_freeze_profundidad. Después de esto, el kernel espera a que la cola se vacíe. .
El tiempo que lleva borrar esta cola es equivalente a la latencia del disco, ya que el kernel espera a que se completen todas las operaciones en cola. Una vez que la cola está vacía, se aplican los cambios de configuración. Después de lo cual se llama , disminuyendo el contador congelar_profundidad.
Ahora sabemos lo suficiente para corregir la situación. El comando de activación udevadm hace que se aplique la configuración del dispositivo de bloque. Estas configuraciones se describen en las reglas de udev. Podemos encontrar qué configuraciones están congelando la cola intentando cambiarlas a través de sysfs o mirando el código fuente del kernel. También podemos probar la utilidad BCC. , que generará seguimientos de la pila del kernel y del espacio de usuario para cada llamada al terminal blk_freeze_queue, Por ejemplo:
~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U
PID TID COMM FUNC
3809642 3809642 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
elevator_switch+0x29 [kernel]
elv_iosched_store+0x197 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
3809631 3809631 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
queue_requests_store+0xb6 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
Las reglas de Udev cambian muy raramente y normalmente esto sucede de forma controlada. Entonces vemos que incluso aplicar los valores ya establecidos provoca un aumento en el retraso en la transferencia de la solicitud desde la aplicación al disco. Por supuesto, generar eventos udev cuando no hay cambios en la configuración del disco (por ejemplo, el dispositivo no está montado/desconectado) no es una buena práctica. Sin embargo, podemos ayudar al kernel a no realizar trabajos innecesarios y congelar la cola de solicitudes si no es necesario. corregir la situación.
Conclusión
eBPF es una herramienta muy flexible y poderosa. En el artículo analizamos un caso práctico y demostramos una pequeña parte de lo que se puede hacer. Si está interesado en desarrollar utilidades BCC, vale la pena echarle un vistazo , que describe bien los conceptos básicos.
Existen otras herramientas interesantes de depuración y creación de perfiles basadas en eBPF. Uno de ellos - , que le permite escribir potentes frases ingeniosas y pequeños programas en un lenguaje similar a awk. Otro - , le permite recopilar métricas de alta resolución y bajo nivel directamente en su servidor Prometheus, con la capacidad de obtener posteriormente hermosas visualizaciones e incluso alertas.
Fuente: habr.com
