Linux ten unha gran cantidade de ferramentas para depurar o núcleo e as aplicacións. A maioría deles teñen un impacto negativo no rendemento da aplicación e non se poden usar na produción.
Hai un par de anos houbo - eBPF. Permite rastrexar o núcleo e as aplicacións do usuario con pouca sobrecarga e sen necesidade de reconstruír programas e cargar módulos de terceiros no núcleo.
Xa hai moitas utilidades de aplicacións que usan eBPF, e neste artigo veremos como escribir a túa propia utilidade de creación de perfiles baseada na biblioteca . O artigo está baseado en feitos reais. Pasaremos de problema en solución para mostrar como se poden usar as utilidades existentes en situacións específicas.
Ceph é lento
Engadiuse un novo host ao clúster Ceph. Despois de migrar algúns dos datos a el, observamos que a velocidade de procesamento das solicitudes de escritura era moito menor que noutros servidores.
A diferenza doutras plataformas, este servidor utilizou bcache e o novo núcleo de linux 4.15. Esta foi a primeira vez que se utilizou aquí un host desta configuración. E nese momento estaba claro que a raíz do problema podía ser teoricamente calquera cousa.
Investigando o Host
Comecemos mirando o que ocorre dentro do proceso ceph-osd. Para iso utilizaremos и (máis sobre o que podes ler ):
A imaxe dinos que a función fdatasync() pasou moito tempo enviando unha solicitude ás funcións generic_make_request(). Isto significa que o máis probable é que a causa dos problemas estea nalgún lugar fóra do propio daemon osd. Este pode ser o núcleo ou os discos. A saída de iostat mostrou unha alta latencia no procesamento das solicitudes dos discos bcache.
Ao comprobar o host, descubrimos que o daemon systemd-udevd consume unha gran cantidade de tempo de CPU, aproximadamente un 20% en varios núcleos. Este é un comportamento estraño, polo que debes descubrir por que. Dado que Systemd-udevd funciona con uevents, decidimos analizalos monitor udevadm. Resulta que se xeraron un gran número de eventos de cambio para cada dispositivo de bloque do sistema. Isto é bastante inusual, polo que teremos que ver o que xera todos estes eventos.
Usando o BCC Toolkit
Como xa descubrimos, o núcleo (e o daemon ceph na chamada do sistema) pasa moito tempo en generic_make_request(). Intentemos medir a velocidade desta función. EN Xa hai unha utilidade marabillosa - funcionalidade. Trazaremos o daemon polo seu PID cun intervalo de 1 segundo entre saídas e mostraremos o resultado en milisegundos.
Esta función normalmente funciona rapidamente. Todo o que fai é pasar a solicitude á cola do controlador do dispositivo.
Bcache é un dispositivo complexo que en realidade consta de tres discos:
- dispositivo de respaldo (disco almacenado en caché), neste caso é un disco duro lento;
- dispositivo de caché (disco de caché), aquí esta é unha partición do dispositivo NVMe;
- o dispositivo virtual bcache co que se executa a aplicación.
Sabemos que a transmisión de solicitudes é lenta, pero para cal destes dispositivos? Tratarémolo un pouco máis tarde.
Agora sabemos que é probable que os eventos causen problemas. Atopar o que causa exactamente a súa xeración non é tan sinxelo. Supoñamos que este é algún tipo de software que se lanza periodicamente. Vexamos que tipo de software se executa no sistema mediante un script execsnoop do mesmo . Imos executalo e enviar a saída a un ficheiro.
Por exemplo así:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Non mostraremos aquí a saída completa de execsnoop, pero unha liña de interese para nós parecía a seguinte:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
A terceira columna é o PPID (PID principal) do proceso. O proceso con PID 5802 resultou ser un dos fíos do noso sistema de monitorización. Ao comprobar a configuración do sistema de vixilancia atopáronse parámetros erróneos. A temperatura do adaptador HBA tomouse cada 30 segundos, o que é moito máis frecuente do necesario. Despois de cambiar o intervalo de comprobación a outro máis longo, descubrimos que a latencia de procesamento de solicitudes neste host xa non destacaba en comparación con outros hosts.
Pero aínda non está claro por que o dispositivo bcache era tan lento. Preparamos unha plataforma de proba cunha configuración idéntica e tentamos reproducir o problema executando fio en bcache, executando periodicamente udevadm trigger para xerar uevents.
Ferramentas de escritura baseadas en BCC
Tentemos escribir unha utilidade sinxela para rastrexar e mostrar as chamadas máis lentas generic_make_request(). Tamén nos interesa o nome da unidade para a que se chamou esta función.
O plan é sinxelo:
- Rexístrate ksonda en generic_make_request():
- Gardamos o nome do disco na memoria, accesible a través do argumento función;
- Gardamos a marca de tempo.
- Rexístrate kretprobe para o regreso de generic_make_request():
- Obtemos a marca de tempo actual;
- Buscamos a marca de tempo gardada e comparámola coa actual;
- Se o resultado é maior que o especificado, entón atopamos o nome do disco gardado e mostrámolo no terminal.
Ksondas и sondas kret use un mecanismo de punto de interrupción para cambiar o código de función sobre a marcha. Podes ler и artigo sobre este tema. Se miras o código de varias utilidades en , entón podes ver que teñen unha estrutura idéntica. Polo tanto, neste artigo omitiremos analizar os argumentos do script e pasaremos ao propio programa BPF.
O texto eBPF dentro do script Python ten o seguinte aspecto:
bpf_text = “”” # Here will be the bpf program code “””
Para intercambiar datos entre funcións, os programas eBPF utilizan . Nós faremos o mesmo. Usaremos o PID do proceso como clave e definiremos a estrutura como o 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í rexistramos unha táboa hash chamada p, con tipo de chave u64 e un valor de tipo struct data_t. A táboa estará dispoñible no contexto do noso programa BPF. A macro BPF_PERF_OUTPUT rexistra outra táboa chamada eventos, que se usa para no espazo de usuario.
Ao medir os atrasos entre a chamada dunha función e o regreso desta, ou entre chamadas a diferentes funcións, cómpre ter en conta que os datos recibidos deben pertencer ao mesmo contexto. Noutras palabras, cómpre lembrar o posible lanzamento paralelo de funcións. Temos a capacidade de medir a latencia entre chamar a unha función no contexto dun proceso e regresar desa función no contexto doutro proceso, pero é probable que isto sexa inútil. Un bo exemplo sería aquí , onde a clave da táboa hash está definida como un punteiro a solicitude de estrutura, que reflicte unha solicitude de disco.
A continuación, necesitamos escribir o código que se executará cando se chame á función en estudo:
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í o primeiro argumento da función chamada substituirase como segundo argumento . Despois diso, obtemos o PID do proceso no contexto no que estamos a traballar e a marca de tempo actual en nanosegundos. Anotamos todo nun recén seleccionado struct data_t datos. Obtemos o nome do disco da estrutura bio, que se pasa ao chamar generic_make_request(), e gárdao na mesma estrutura datos. O último paso é engadir unha entrada á táboa hash que se mencionou anteriormente.
A seguinte función chamarase ao regreso de generic_make_request():
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 é semellante á anterior: descubrimos o PID do proceso e a marca de tempo, pero non asignamos memoria para a nova estrutura de datos. Pola contra, buscamos na táboa hash unha estrutura xa existente usando a chave == PID actual. Se se atopa a estrutura, entón descubrimos o nome do proceso en execución e engadímolo a el.
O desprazamento binario que usamos aquí é necesario para obter o GID do fío. aqueles. PID do proceso principal que iniciou o fío no contexto no que estamos a traballar. A función que chamamos devolve tanto o GID do fío como o seu PID nun único valor de 64 bits.
Ao saír ao terminal, actualmente non nos interesa o fío, pero sí o proceso principal. Despois de comparar o atraso resultante cun determinado limiar, pasamos a nosa estrutura datos no espazo de usuario a través da táboa eventos, despois de que eliminamos a entrada de p.
No script de Python que cargará este código, necesitamos substituír MIN_US e FACTOR polos limiares de atraso e as unidades de tempo, que pasaremos polos 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"
Agora necesitamos preparar o programa BPF vía e rexistrar mostras:
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")
Tamén teremos que determinar struct data_t no noso guión, se non, non poderemos ler 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)]
O último paso é enviar datos ao 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()
O propio guión está dispoñible en . Tentemos executalo nunha plataforma de proba onde fio estea a executar, escribindo en bcache e chamando ao monitor udevadm:
Por fin! Agora vemos que o que parecía un dispositivo bcache parado é en realidade unha chamada parada generic_make_request() para un disco caché.
Cave no núcleo
Que se está a ralentizar exactamente durante a transmisión da solicitude? Vemos que o atraso se produce mesmo antes do inicio da contabilidade da solicitude, é dicir. A contabilización dunha solicitude específica para obter máis estatísticas sobre ela (/proc/diskstats ou iostat) aínda non comezou. Isto pódese verificar facilmente executando iostat mentres se reproduce o problema ou , que se basea no inicio e final da contabilidade da solicitude. Ningunha destas utilidades mostrará problemas para as solicitudes ao disco almacenado na caché.
Se miramos a función generic_make_request(), entón veremos que antes de comezar a contabilidade da solicitude, son chamadas dúas funcións máis. Primeira - generic_make_request_checks(), realiza comprobacións sobre a lexitimidade da solicitude con respecto á configuración do disco. segundo - , que ten un reto interesante :
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));
Nela, o núcleo agarda a que se desconxele a cola. Imos medir o atraso 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 preto dunha solución. As funcións utilizadas para conxelar/desconxelar unha cola son и . Utilízanse cando é necesario cambiar a configuración da cola de solicitudes, que son potencialmente perigosas para as solicitudes desta cola. Ao chamar blk_mq_freeze_queue() función o contador increméntase q->mq_conxelar_profundidade. Despois diso, o núcleo agarda a que se baleira a cola .
O tempo que leva borrar esta cola é equivalente á latencia do disco xa que o núcleo agarda a que se completen todas as operacións da cola. Unha vez que a cola está baleira, aplícanse os cambios de configuración. Despois de que se chama , diminuíndo o contador conxelar_profundidade.
Agora sabemos o suficiente para corrixir a situación. O comando disparador udevadm fai que se aplique a configuración do dispositivo de bloqueo. Estes axustes descríbense nas regras de udev. Podemos atopar cales son os axustes que conxelan a cola tentando cambialos a través de sysfs ou mirando o código fonte do núcleo. Tamén podemos probar a utilidade BCC , que mostrará os rastros da pila do núcleo e do espazo de usuario para cada chamada ao terminal blk_freeze_queue, por exemplo:
~# /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]
As regras de Udev cambian moi poucas veces e normalmente isto ocorre de forma controlada. Entón, vemos que mesmo aplicar os valores xa establecidos provoca un aumento no atraso na transferencia da solicitude da aplicación ao disco. Por suposto, xerar eventos udev cando non hai cambios na configuración do disco (por exemplo, o dispositivo non está montado/desconectado) non é unha boa práctica. Non obstante, podemos axudar ao núcleo a non facer traballos innecesarios e conxelar a cola de solicitudes se non é necesario. corrixir a situación.
Conclusión
eBPF é unha ferramenta moi flexible e poderosa. No artigo analizamos un caso práctico e demostramos unha pequena parte do que se pode facer. Se estás interesado en desenvolver utilidades BCC, paga a pena botarlle unha ollada , que describe ben os conceptos básicos.
Hai outras interesantes ferramentas de depuración e elaboración de perfiles baseadas en eBPF. Un deles - , que che permite escribir potentes one-liners e pequenos programas na linguaxe awk. Outro - , permíteche recoller métricas de baixo nivel e alta resolución directamente no teu servidor prometheus, coa posibilidade de obter máis tarde visualizacións bonitas e mesmo alertas.
Fonte: www.habr.com