Linux dispone di un gran numero di strumenti per il debug del kernel e delle applicazioni. La maggior parte di essi ha un impatto negativo sulle prestazioni dell'applicazione e non può essere utilizzata in produzione.
Un paio di anni fa c'era -eBPF. Rende possibile tracciare il kernel e le applicazioni utente con un basso sovraccarico e senza la necessità di ricostruire programmi e caricare moduli di terze parti nel kernel.
Esistono già molte utilità applicative che utilizzano eBPF e in questo articolo vedremo come scrivere la propria utilità di profilazione basata sulla libreria . L'articolo è basato su eventi reali. Passeremo dal problema alla soluzione per mostrare come le utilità esistenti possono essere utilizzate in situazioni specifiche.
Ceph è lento
Un nuovo host è stato aggiunto al cluster Ceph. Dopo aver migrato alcuni dati su di esso, abbiamo notato che la velocità di elaborazione delle richieste di scrittura era molto inferiore rispetto ad altri server.
A differenza di altre piattaforme, questo host utilizzava BCache e il nuovo kernel Linux 4.15. Questa è stata la prima volta che un host di questa configurazione è stato utilizzato qui. E in quel momento era chiaro che teoricamente la radice del problema poteva essere qualsiasi cosa.
Investigando sull'ospite
Cominciamo guardando cosa succede all'interno del processo cefalo-osd. Per questo useremo и (di più su cui puoi leggere ):
L'immagine ci dice che la funzione fdatasync() ha passato molto tempo a inviare una richiesta alle funzioni generic_make_request(). Ciò significa che molto probabilmente la causa dei problemi è da qualche parte al di fuori del demone OSD stesso. Può trattarsi del kernel o dei dischi. L'output di iostat ha mostrato un'elevata latenza nell'elaborazione delle richieste da parte dei dischi bcache.
Controllando l'host, abbiamo scoperto che il demone systemd-udevd consuma una grande quantità di tempo della CPU, circa il 20% su diversi core. Questo è un comportamento strano, quindi devi scoprire perché. Dato che Systemd-udevd funziona con uevents, abbiamo deciso di esaminarli attentamente monitor udevadm. Risulta che è stato generato un gran numero di eventi di modifica per ciascun dispositivo a blocchi nel sistema. Questo è abbastanza insolito, quindi dovremo guardare cosa genera tutti questi eventi.
Utilizzando il toolkit BCC
Come abbiamo già scoperto, il kernel (e il demone ceph nella chiamata di sistema) trascorre molto tempo in generic_make_request(). Proviamo a misurare la velocità di questa funzione. IN Esiste già un'utilità meravigliosa: funzionalità. Tracceremo il demone in base al suo PID con un intervallo di 1 secondo tra gli output e visualizzeremo il risultato in millisecondi.
Questa funzione di solito funziona rapidamente. Tutto ciò che fa è passare la richiesta alla coda del driver del dispositivo.
BCache è un dispositivo complesso che in realtà è composto da tre dischi:
- dispositivo di backup (disco memorizzato nella cache), in questo caso si tratta di un HDD lento;
- dispositivo di memorizzazione nella cache (disco di memorizzazione nella cache), in questo caso si tratta di una partizione del dispositivo NVMe;
- il dispositivo virtuale bcache con cui viene eseguita l'applicazione.
Sappiamo che la trasmissione delle richieste è lenta, ma per quale di questi dispositivi? Ci occuperemo di questo un po' più tardi.
Ora sappiamo che è probabile che gli eventi causino problemi. Trovare cosa causa esattamente la loro generazione non è così facile. Supponiamo che si tratti di una sorta di software che viene lanciato periodicamente. Vediamo che tipo di software viene eseguito sul sistema utilizzando uno script execsnoop dallo stesso . Eseguiamolo e inviamo l'output in un file.
Ad esempio, in questo modo:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Non mostreremo qui l’intero output di execsnoop, ma una riga che ci interessava assomigliava a questa:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
La terza colonna è il PPID (PID genitore) del processo. Il processo con PID 5802 si è rivelato uno dei fili del nostro sistema di monitoraggio. Durante il controllo della configurazione del sistema di monitoraggio sono stati rilevati parametri errati. La temperatura dell'adattatore HBA è stata misurata ogni 30 secondi, ovvero molto più spesso del necessario. Dopo aver modificato l'intervallo di controllo impostandolo su uno più lungo, abbiamo riscontrato che la latenza di elaborazione delle richieste su questo host non si distingueva più rispetto ad altri host.
Ma non è ancora chiaro il motivo per cui il dispositivo bcache fosse così lento. Abbiamo preparato una piattaforma di test con una configurazione identica e abbiamo provato a riprodurre il problema eseguendo fio su bcache, eseguendo periodicamente il trigger udevadm per generare uevents.
Scrittura di strumenti basati su BCC
Proviamo a scrivere una semplice utility per tracciare e visualizzare le chiamate più lente generic_make_request(). Ci interessa anche il nome dell'unità per la quale è stata chiamata questa funzione.
Il piano è semplice:
- Registrati kprobe su generic_make_request():
- Salviamo il nome del disco in memoria, accessibile tramite l'argomento funzione;
- Salviamo il timestamp.
- Registrati kretprobe per il ritorno da generic_make_request():
- Otteniamo il timestamp corrente;
- Cerchiamo il timestamp salvato e confrontiamolo con quello attuale;
- Se il risultato è maggiore di quello specificato, troviamo il nome del disco salvato e lo visualizziamo sul terminale.
Kprobes и kretprobes utilizzare un meccanismo di breakpoint per modificare al volo il codice funzione. Puoi leggere и articolo su questo argomento. Se guardi il codice di varie utilità in , allora puoi vedere che hanno una struttura identica. Quindi in questo articolo salteremo l'analisi degli argomenti dello script e passeremo al programma BPF stesso.
Il testo eBPF all'interno dello script Python è simile al seguente:
bpf_text = “”” # Here will be the bpf program code “””
Per scambiare dati tra funzioni, i programmi eBPF utilizzano . Faremo lo stesso. Utilizzeremo il PID del processo come chiave e definiremo la struttura come valore:
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);
Qui registriamo una tabella hash chiamata p, con tipo di chiave u64 e un valore di tipo struttura dati_t. La tabella sarà disponibile nel contesto del nostro programma BPF. La macro BPF_PERF_OUTPUT registra un'altra tabella chiamata eventi, che viene utilizzato per nello spazio utente.
Quando si misurano i ritardi tra la chiamata di una funzione e il ritorno da essa, o tra le chiamate a funzioni diverse, è necessario tenere conto del fatto che i dati ricevuti devono appartenere allo stesso contesto. In altre parole, è necessario ricordare il possibile lancio parallelo di funzioni. Abbiamo la capacità di misurare la latenza tra la chiamata di una funzione nel contesto di un processo e il ritorno da quella funzione nel contesto di un altro processo, ma questo è probabilmente inutile. Un buon esempio qui sarebbe , dove la chiave della tabella hash è impostata su un puntatore a richiesta di struttura, che riflette una richiesta del disco.
Successivamente, dobbiamo scrivere il codice che verrà eseguito quando verrà chiamata la funzione in studio:
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);
}
Qui il primo argomento della funzione chiamata verrà sostituito come secondo argomento . Successivamente, otteniamo il PID del processo nel contesto del quale stiamo lavorando e il timestamp attuale in nanosecondi. Scriviamo tutto in modo appena selezionato struttura dati_t dati. Otteniamo il nome del disco dalla struttura bio, che viene passato durante la chiamata generic_make_request()e salvarlo nella stessa struttura dati. L'ultimo passaggio consiste nell'aggiungere una voce alla tabella hash menzionata in precedenza.
La seguente funzione verrà chiamata al ritorno da 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);
}
}
Questa funzione è simile alla precedente: scopriamo il PID del processo e il timestamp, ma non allochiamo memoria per la nuova struttura dati. Cerchiamo invece nella tabella hash una struttura già esistente utilizzando la chiave == PID corrente. Se la struttura viene trovata, scopriamo il nome del processo in esecuzione e lo aggiungiamo ad esso.
Lo spostamento binario che usiamo qui è necessario per ottenere il GID del thread. quelli. PID del processo principale che ha avviato il thread nel contesto del quale stiamo lavorando. La funzione che chiamiamo restituisce sia il GID che il PID del thread in un unico valore a 64 bit.
Durante l'output sul terminale, al momento non siamo interessati al thread, ma siamo interessati al processo principale. Dopo aver confrontato il ritardo risultante con una determinata soglia, passiamo alla nostra struttura dati nello spazio utente tramite tabella eventi, dopodiché eliminiamo la voce da p.
Nello script Python che caricherà questo codice, dobbiamo sostituire MIN_US e FACTOR con le soglie di ritardo e le unità di tempo, che passeremo attraverso gli argomenti:
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"
Ora dobbiamo preparare il programma BPF via e registrare i campioni:
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")
Dovremo anche determinarlo struttura dati_t nel nostro script, altrimenti non saremo in grado di leggere nulla:
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)]
L'ultimo passo è inviare i dati al terminale:
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()
Lo script stesso è disponibile su . Proviamo a eseguirlo su una piattaforma di test in cui fio è in esecuzione, scrive su bcache e chiama udevadm monitor:
Finalmente! Ora vediamo che quello che sembrava un dispositivo bcache in stallo è in realtà una chiamata in stallo generic_make_request() per un disco memorizzato nella cache.
Scava nel Kernel
Cos'è esattamente il rallentamento durante la trasmissione della richiesta? Vediamo che il ritardo si verifica anche prima dell'inizio della contabilizzazione della richiesta, vale a dire la contabilizzazione di una specifica richiesta di ulteriore output di statistiche su di esso (/proc/diskstats o iostat) non è ancora iniziata. Ciò può essere facilmente verificato eseguendo iostat durante la riproduzione del problema oppure , che si basa sulla contabilità di inizio e fine richiesta. Nessuna di queste utilità mostrerà problemi per le richieste al disco memorizzato nella cache.
Se guardiamo la funzione generic_make_request(), allora vedremo che prima che la richiesta inizi a contabilizzare, vengono chiamate altre due funzioni. Primo - generic_make_request_checks(), effettua controlli sulla legittimità della richiesta relativa alle impostazioni del disco. Secondo - , che presenta una sfida interessante :
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));
In esso, il kernel attende che la coda si sblocchi. Misuriamo il ritardo 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 | |
Sembra che siamo vicini a una soluzione. Le funzioni utilizzate per bloccare/sbloccare una coda sono и . Vengono utilizzati quando è necessario modificare le impostazioni della coda di richieste, che sono potenzialmente pericolose per le richieste in questa coda. Quando chiami blk_mq_freeze_queue() функцией il contatore viene incrementato q->mq_congela_profondità. Successivamente, il kernel attende che la coda si svuoti .
Il tempo necessario per cancellare questa coda equivale alla latenza del disco poiché il kernel attende il completamento di tutte le operazioni in coda. Una volta che la coda è vuota, le modifiche alle impostazioni vengono applicate. Dopodiché viene chiamato , decrementando il contatore freeze_profondità.
Ora sappiamo abbastanza per correggere la situazione. Il comando trigger udevadm fa sì che vengano applicate le impostazioni per il dispositivo a blocchi. Queste impostazioni sono descritte nelle regole udev. Possiamo scoprire quali impostazioni bloccano la coda provando a modificarle tramite sysfs o guardando il codice sorgente del kernel. Possiamo anche provare l'utilità BCC , che genererà le tracce dello stack del kernel e dello spazio utente per ogni chiamata al terminale blk_freeze_queue, ad esempio:
~# /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]
Le regole dell'Udev cambiano abbastanza raramente e solitamente ciò avviene in maniera controllata. Quindi vediamo che anche l'applicazione dei valori già impostati provoca un picco nel ritardo nel trasferimento della richiesta dall'applicazione al disco. Naturalmente, generare eventi udev quando non ci sono modifiche nella configurazione del disco (ad esempio, il dispositivo non è montato/disconnesso) non è una buona pratica. Tuttavia, possiamo aiutare il kernel a non svolgere lavoro non necessario e a congelare la coda delle richieste se non è necessario. correggere la situazione.
Conclusione
eBPF è uno strumento molto flessibile e potente. Nell'articolo abbiamo esaminato un caso pratico e dimostrato una piccola parte di ciò che si può fare. Se sei interessato allo sviluppo di utilità BCC, vale la pena dare un'occhiata , che descrive bene le nozioni di base.
Esistono altri interessanti strumenti di debug e profilazione basati su eBPF. Uno di loro - , che ti consente di scrivere potenti battute e piccoli programmi nel linguaggio simile a awk. Un altro - , ti consente di raccogliere parametri di basso livello e ad alta risoluzione direttamente nel tuo server Prometheus, con la possibilità di ottenere successivamente splendide visualizzazioni e persino avvisi.
Fonte: habr.com