In Linux ci sono molti strumenti per il debug del kernel e delle applicazioni. La maggior parte di essi ha un impatto negativo sulle prestazioni delle applicazioni e non può essere utilizzata in produzione.
Qualche anno fa è stato — eBPF. Esso consente di tracciare il kernel e le applicazioni utente con un sovraccarico minimo e senza la necessità di ricompilare i programmi o caricare moduli esterni nel kernel.
Adesso esistono già numerose utilità pratiche che utilizzano eBPF, e in questo articolo esploreremo come scrivere la nostra utilità per il profiling basata sulla libreria . L'articolo è basato su eventi reali. Percorreremo il cammino dalla nascita del problema alla sua risoluzione, per mostrare come possono essere utilizzate le utilità esistenti in situazioni specifiche.
Ceph È Lento
Un nuovo host è stato aggiunto al cluster Ceph. Dopo la migrazione di parte dei 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, su questo host è stato utilizzato bcache e un nuovo kernel linux 4.15. Un host di questa configurazione era utilizzato qui per la prima volta. E a quel tempo era chiaro che la causa del problema teoricamente poteva essere qualsiasi cosa.
Indagando sull'Host
Iniziamo a vedere cosa succede all'interno del processo ceph-osd. A tal fine utilizzeremo e (puoi leggere di più su di esso ):
L'immagine ci dice che la funzione fdatasync() ha impiegato molto tempo nell'invio della richiesta nella funzione generic_make_request(). Ciò significa che probabilmente, la causa dei problemi è da cercare al di fuori stesso del demone osd. Potrebbe essere o il kernel o i dischi. L'output di iostat mostrava un'elevata latenza nell'elaborazione delle richieste dai dischi bcache.
Durante il controllo dell'host abbiamo scoperto che il demone systemd-udevd consuma un grande quantitativo di tempo CPU — circa il 20% su più core. Questo comportamento è strano, quindi bisogna scoprire la sua causa. Poiché Systemd-udevd lavora con gli uevent, abbiamo deciso di esaminarli tramite udevadm monitor. Si è scoperto che venivano generati un gran numero di eventi di tipo change per ciascun dispositivo a blocchi nel sistema. Questo è piuttosto insolito, quindi sarà necessario vedere cosa genera tutti questi eventi.
Utilizzando il Toolkit BCC
Come abbiamo già scoperto, il kernel (e il demone ceph nella chiamata di sistema) spende molto tempo in generic_make_request(). Proviamo a misurare la velocità di funzionamento di questa funzione. In già esiste un'ottima utility — funclatency. Tracceremo il demone in base al suo PID con un intervallo tra le stampe di informazioni di 1 secondo e mostreremo il risultato in millisecondi.
Di solito questa funzione funziona rapidamente. Tutto ciò che fa è inoltrare la richiesta nella coda del driver del dispositivo.
Bcache è un dispositivo complesso che in realtà è composto da tre dischi:
- dispositivo di backing (disco cacheabile), in questo caso è un HDD lento;
- dispositivo di caching (disco cache), qui è una partizione di un dispositivo NVMe;
- dispositivo virtuale bcache, con cui lavora l'applicazione.
Sappiamo che la trasmissione della richiesta rallenta, ma per quale di questi dispositivi? Approfondiremo questo più tardi.
Al momento sappiamo che gli uevent probabilmente causano problemi. Trovare cosa genera la loro creazione non è così semplice. Supponiamo che sia qualche software che viene eseguito periodicamente. Vediamo quale software viene avviato nel sistema, utilizzando lo script execsnoop della stessa . Avviamolo e indirizziamo l'output in un file.
Ad esempio in questo modo:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Non presenteremo qui l'output completo di execsnoop, ma una riga che ci interessa appariva così:
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 (parent PID) del processo. Il processo con PID 5802 si è rivelato essere uno dei thread del nostro sistema di monitoraggio. Durante il controllo della configurazione del sistema di monitoraggio sono stati trovati parametri impostati erroneamente. La temperatura dell'adattatore HBA veniva rilevata ogni 30 secondi, molto più spesso del necessario. Dopo aver cambiato l'intervallo di controllo in un intervallo più lungo, abbiamo scoperto che il ritardo nel trattamento delle richieste su questo host non si evidenziava più rispetto agli altri host.
Ma non è ancora chiaro perché il dispositivo bcache fosse così lento. Abbiamo preparato una piattaforma di test con configurazione identica e abbiamo provato a riprodurre il problema, eseguendo fio su bcache, avviando periodicamente udevadm trigger per generare uevents.
Scrittura di Strumenti Basati su BCC
Proviamo a scrivere una semplice utilità per tracciare e visualizzare le chiamate più lente generic_make_request(). Ci interessa anche il nome del disco per il quale è stata chiamata questa funzione.
Il piano è semplice:
- Registriamo kprobe in generic_make_request():
- Salviamo in memoria il nome del disco, disponibile tramite l'argomento della funzione;
- Salviamo il timestamp.
- Registriamo kretprobe al ritorno da generic_make_request():
- Otteniamo l'attuale timestamp;
- Cerchiamo il timestamp salvato e lo confrontiamo con quello attuale;
- Se il risultato è maggiore di quanto specificato, troviamo il nome del disco salvato e lo visualizziamo nel terminale.
Kprobes e kretprobes utilizzano un meccanismo di breakpoint per modificare il codice delle funzioni al volo. Puoi leggere e articolo su questo argomento. Se osserviamo il codice di varie utility in , si può notare che hanno una struttura identica. Quindi, in questo articolo, ometteremo il parsing degli argomenti dello script e passeremo direttamente al programma BPF.
Il testo eBPF all'interno dello script python appare come segue:
bpf_text = ''' # Qui ci sarà il codice del programma bpf '''
Per lo scambio di dati tra funzioni, i programmi eBPF utilizzano . Procediamo allo stesso modo. Come chiave, utilizzeremo il PID del processo, mentre come valore definiremo la seguente struttura:
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 chiave di tipo u64 e valore di tipo struct data_t. La tabella sarà disponibile nel contesto del nostro programma BPF. Il macro BPF_PERF_OUTPUT registra un'altra tabella, chiamata events, che viene utilizzata per allo spazio utente.
Quando si misurano i ritardi tra la chiamata a una funzione e il ritorno da essa, o tra le chiamate a funzioni diverse, è necessario tenere presente che i dati ottenuti devono appartenere a un unico contesto. In altre parole, bisogna ricordare la possibilità di esecuzioni parallele delle funzioni. Abbiamo la possibilità di misurare il ritardo tra la chiamata di una funzione nel contesto di un processo e il ritorno da questa funzione nel contesto di un altro processo, ma probabilmente non sarà utile. Un buon esempio è dato dall' , in cui come chiave della tabella hash viene utilizzato un puntatore a struct request, che rappresenta una richiesta al disco.
Ora dobbiamo scrivere il codice che verrà eseguito al momento della chiamata della funzione analizzata:
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 secondo argomento sarà sostituito dal primo argomento della funzione chiamata . Dopo di ciò otteniamo il PID del processo, nel contesto del quale stiamo operando, e il timestamp attuale in nanosecondi. Registriamo tutto questo nella memoria appena allocata struct data_t data. Il nome del disco lo otteniamo dalla struttura bio, che viene passata durante la chiamata generic_make_request(), e lo memorizziamo nella stessa struttura data. L'ultimo passo consiste nell'aggiungere una registrazione nella tabella hash, di cui si è parlato in precedenza.
La funzione successiva 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: otteniamo il PID del processo e il timestamp, ma non allocchiamo memoria per una nuova struttura data. Invece, cerchiamo nella tabella hash una struttura esistente con la chiave pari al PID attuale. Se la struttura viene trovata, otteniamo il nome del processo in esecuzione e lo aggiungiamo ad essa.
Lo spostamento binario che usiamo qui è necessario per ottenere il GID del thread, cioè il PID del processo principale che ha avviato il thread, nel contesto del quale stiamo lavorando. La funzione che chiamiamo restituisce sia il GID del thread che il suo PID in un singolo valore a 64 bit.
Nel terminale non ci interessa attualmente il thread, ma il processo principale. Dopo aver confrontato la latenza ottenuta con la soglia specificata, trasmettiamo la nostra struttura data allo spazio utente tramite la tabella events, dopodiché eliminiamo la registrazione da p.
Nel script python che caricherà questo codice, dobbiamo sostituire MIN_US e FACTOR con le soglie di latenza e le unità di tempo che passeremo come 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 tramite e registrare i probe:
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")
Dobbiamo anche definire struct data_t nel nostro script, altrimenti non possiamo 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 è l'uscita dei dati sul 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 dove è in esecuzione fio, che scrive su bcache, e a chiamare udevadm monitor:
Finalmente! Ora vediamo che ciò che sembrava un dispositivo bcache in rallentamento, in realtà è una chiamata lenta generic_make_request() per il disco in cache.
Approfondiamo il Kernel
Cosa causa il rallentamento durante l'invio della richiesta? Vediamo che il ritardo si verifica anche prima dell'inizio del conteggio della richiesta, ovvero la registrazione di una specifica richiesta per ulteriori statistiche ( /proc/diskstats o iostat) non è ancora iniziata. Può essere facilmente verificato eseguendo iostat durante la riproduzione del problema, oppure , che si basa sull'inizio e sulla fine della registrazione delle richieste. Nessuna di queste utilità mostrerà problemi per le richieste al disco in cache.
Se diamo un'occhiata alla funzione generic_make_request(), vedremo che prima dell'inizio del conteggio della richiesta vengono chiamate altre due funzioni. La prima è generic_make_request_checks(), che esegue controlli di legittimità della richiesta rispetto alle impostazioni del disco. La seconda è , in cui c'è una chiamata interessante a :
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));
Qui il kernel attende lo scongelamento della coda. Misuriamo il ritardo blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Tracciando 1 funzioni per "blk_queue_enter"... Premi Ctrl-C per terminare.
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 alla soluzione. Le funzioni utilizzate per "congelare/scongelare" la coda sono e . Vengono utilizzate quando è necessario modificare le impostazioni della coda delle richieste, potenzialmente pericolose per le richieste nella coda stessa. Al momento della chiamata blk_mq_freeze_queue() da parte della funzione il contatore viene incrementato q->mq_freeze_depth. Dopo di ciò, il kernel attende che la coda venga svuotata in .
Il tempo di attesa per svuotare questa coda è equivalente al ritardo del disco, poiché il kernel aspetta la conclusione di tutte le operazioni messe in coda. Non appena la coda è vuota, vengono applicate le modifiche alle impostazioni. Dopodiché viene chiamata , che decrementa il contatore freeze_depth.
Ora sappiamo abbastanza per risolvere la situazione. Il comando udevadm trigger, in effetti, porta all'applicazione delle impostazioni per il dispositivo a blocchi. Queste impostazioni sono descritte nelle regole di udev. Possiamo scoprire quali impostazioni 'congelano' la coda, provando a modificarle tramite sysfs oppure guardando il codice sorgente del kernel. Inoltre, possiamo provare l'utilità BCC , che mostrerà nel terminale i tracciati dello stack del kernel e dello spazio utente per ogni chiamata blk_freeze_queue, per 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 di Udev cambiano piuttosto raramente e di solito in modo controllato. Quindi, vediamo che anche l'applicazione di valori già definiti provoca un'impennata del ritardo nella trasmissione della richiesta dall'applicazione al disco. Certamente, generare eventi udev quando non ci sono cambiamenti nella configurazione dei dischi (ad esempio, quando un dispositivo non viene collegato/disconnesso) non è una pratica molto utile. Tuttavia, possiamo aiutare il kernel a non svolgere lavoro inutile e non 'congelare' la coda delle richieste, se non è realmente necessario. risolvono la situazione.
Conclusione
eBPF è uno strumento molto flessibile e potente. In questo articolo abbiamo esaminato un caso pratico e dimostrato una piccola parte di ciò che è possibile fare. Se sei interessato allo sviluppo di strumenti BCC, vale la pena dare un'occhiata al , che descrive bene le basi del lavoro.
Ci sono anche altri strumenti interessanti per il debug e il profiling basati su eBPF. Uno di questi è , che consente di scrivere potenti one-liner e piccoli programmi in un linguaggio simile a awk. L'altro è , che consente di raccogliere metriche di basso livello ad alta risoluzione direttamente nel tuo server prometheus, con la possibilità di ottenere in seguito belle visualizzazioni e persino avvisi.
Fonte: habr.com
