Linux ima veliki broj alata za otklanjanje grešaka u kernelu i aplikacijama. Većina njih ima negativan utjecaj na performanse aplikacije i ne može se koristiti u proizvodnji.
Bio je prije par godina — eBPF. Omogućava praćenje kernela i korisničkih aplikacija sa malim troškovima i bez potrebe za ponovnom izgradnjom programa i učitavanjem modula treće strane u kernel.
Već postoji mnogo uslužnih programa koji koriste eBPF, a u ovom članku ćemo pogledati kako napisati svoj vlastiti uslužni program za profiliranje na temelju biblioteke . Članak je zasnovan na stvarnim događajima. Ići ćemo od problema do popravka kako bismo pokazali kako se postojeći uslužni programi mogu koristiti u određenim situacijama.
Ceph je spor
Novi host je dodan u Ceph klaster. Nakon migracije nekih podataka na njega, primijetili smo da je brzina obrade zahtjeva za pisanje od njega bila mnogo manja nego na drugim serverima.
Za razliku od drugih platformi, ovaj host koristi bcache i novo jezgro Linuxa 4.15. Ovo je bio prvi put da je domaćin ove konfiguracije korišten ovdje. I u tom trenutku je bilo jasno da bi koren problema teoretski mogao biti bilo šta.
Istražujem domaćina
Počnimo tako što ćemo pogledati šta se dešava unutar ceph-osd procesa. Za ovo ćemo koristiti и (više o tome možete pročitati ):
Slika nam govori da je funkcija fdatasync() proveo dosta vremena slanjem zahtjeva funkcijama generic_make_request(). To znači da je najvjerovatnije uzrok problema negdje izvan samog osd demona. To može biti ili kernel ili diskovi. Iostat izlaz je pokazao veliko kašnjenje u obradi zahtjeva od strane bcache diskova.
Provjeravajući host, otkrili smo da systemd-udevd daemon troši veliku količinu CPU vremena - oko 20% na nekoliko jezgara. Ovo je čudno ponašanje, pa morate otkriti zašto. Pošto Systemd-udevd radi sa događajima, odlučili smo da ih pogledamo do kraja udevadm monitor. Ispostavilo se da je veliki broj događaja promjene generiran za svaki blok uređaj u sistemu. Ovo je prilično neobično, pa ćemo morati pogledati šta generiše sve ove događaje.
Korištenje BCC Toolkit-a
Kao što smo već saznali, kernel (i ceph daemon u sistemskom pozivu) provodi dosta vremena u generic_make_request(). Pokušajmo izmjeriti brzinu ove funkcije. IN Već postoji divan uslužni program - funclatency. Pratit ćemo demon pomoću njegovog PID-a sa intervalom od 1 sekunde između izlaza i ispisati rezultat u milisekundama.
Ova funkcija obično radi brzo. Sve što radi je prosljeđivanje zahtjeva u red čekanja drajvera uređaja.
Bcache je složen uređaj koji se zapravo sastoji od tri diska:
- prateći uređaj (keširani disk), u ovom slučaju to je spor HDD;
- keš uređaj (caching disk), ovdje je ovo jedna particija NVMe uređaja;
- bcache virtuelni uređaj sa kojim se aplikacija pokreće.
Znamo da je prijenos zahtjeva spor, ali za koji od ovih uređaja? Pozabavićemo se ovim malo kasnije.
Sada znamo da će događaji vjerovatno uzrokovati probleme. Pronaći šta tačno uzrokuje njihovu generaciju nije tako lako. Pretpostavimo da je ovo neka vrsta softvera koji se povremeno pokreće. Hajde da vidimo kakav softver radi na sistemu koristeći skriptu execsnoop od istog . Pokrenimo ga i pošaljimo izlaz u datoteku.
Na primjer ovako:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Ovdje nećemo prikazati kompletan izlaz execsnoop-a, ali jedna linija koja nas zanima izgledala je ovako:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Treći stupac je PPID (roditeljski PID) procesa. Ispostavilo se da je proces sa PID 5802 jedna od niti našeg nadzornog sistema. Prilikom provjere konfiguracije sistema za nadzor, pronađeni su pogrešni parametri. Temperatura HBA adaptera mjerena je svakih 30 sekundi, što je mnogo češće nego što je potrebno. Nakon promjene intervala provjere na duži, otkrili smo da se kašnjenje obrade zahtjeva na ovom hostu više ne ističe u odnosu na druge hostove.
Ali još uvijek je nejasno zašto je bcache uređaj bio tako spor. Pripremili smo testnu platformu sa identičnom konfiguracijom i pokušali da reproduciramo problem pokretanjem fio na bcache, periodično pokretanjem udevadm triggera za generisanje ueventa.
Pisanje alata zasnovanih na BCC-u
Pokušajmo napisati jednostavan uslužni program za praćenje i prikaz najsporijih poziva generic_make_request(). Zanima nas i naziv pogona za koji je ova funkcija pozvana.
Plan je jednostavan:
- Registrirajte se kprobe na generic_make_request():
- Ime diska pohranjujemo u memoriju, dostupnom preko argumenta funkcije;
- Sačuvamo vremensku oznaku.
- Registrirajte se kretprobe za povratak iz generic_make_request():
- Dobijamo trenutnu vremensku oznaku;
- Tražimo sačuvanu vremensku oznaku i upoređujemo je sa trenutnom;
- Ako je rezultat veći od navedenog, tada nalazimo spremljeno ime diska i prikazujemo ga na terminalu.
Kprobes и kretprobes koristite mehanizam prekida za promjenu koda funkcije u hodu. Možete čitati и članak na ovu temu. Ako pogledate kod raznih uslužnih programa u , tada možete vidjeti da imaju identičnu strukturu. Stoga ćemo u ovom članku preskočiti raščlanjivanje argumenata skripte i prijeći na sam BPF program.
eBPF tekst unutar python skripte izgleda ovako:
bpf_text = “”” # Here will be the bpf program code “””
Za razmjenu podataka između funkcija koriste se eBPF programi . I mi ćemo učiniti isto. Koristićemo proces PID kao ključ, a strukturu ćemo definisati kao vrednost:
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);
Ovdje registrujemo hash tablicu tzv p, sa tipom ključa u64 i vrijednost tipa struct data_t. Tabela će biti dostupna u kontekstu našeg BPF programa. BPF_PERF_OUTPUT makro registruje drugu tabelu koja se zove događaji, koji se koristi za u korisnički prostor.
Prilikom mjerenja kašnjenja između poziva funkcije i vraćanja iz nje, ili između poziva različitim funkcijama, morate uzeti u obzir da primljeni podaci moraju pripadati istom kontekstu. Drugim riječima, morate se sjetiti mogućeg paralelnog pokretanja funkcija. Imamo mogućnost da izmerimo kašnjenje između poziva funkcije u kontekstu jednog procesa i vraćanja iz te funkcije u kontekstu drugog procesa, ali to je verovatno beskorisno. Dobar primjer bi ovdje bio , gdje je ključ hash tablice postavljen na pokazivač na struct zahtjev, koji odražava jedan zahtjev za diskom.
Zatim moramo napisati kod koji će se pokrenuti kada se pozove funkcija koja se proučava:
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);
}
Ovdje će prvi argument pozvane funkcije biti zamijenjen kao drugi argument . Nakon toga dobijamo PID procesa u kojem radimo i trenutnu vremensku oznaku u nanosekundama. Sve to zapisujemo u svježe odabrano struct data_t data. Ime diska dobijamo iz strukture Bio, koji se prenosi prilikom poziva generic_make_request(), i sačuvajte ga u istoj strukturi podaci. Posljednji korak je dodavanje unosa u hash tablicu koja je ranije spomenuta.
Sljedeća funkcija će biti pozvana po povratku iz 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);
}
}
Ova funkcija je slična prethodnoj: saznajemo PID procesa i vremensku oznaku, ali ne dodjeljujemo memoriju za novu strukturu podataka. Umjesto toga, tražimo u hash tablici već postojeću strukturu koristeći ključ == trenutni PID. Ako je struktura pronađena, tada saznajemo ime pokrenutog procesa i dodajemo mu ga.
Binarni pomak koji ovdje koristimo je potreban da dobijemo GID niti. one. PID glavnog procesa koji je pokrenuo nit u čijem kontekstu radimo. Funkcija koju zovemo vraća i GID niti i njen PID u jednoj 64-bitnoj vrijednosti.
Prilikom izlaza na terminal, trenutno nas ne zanima stream, ali nas zanima glavni proces. Nakon poređenja rezultirajućeg kašnjenja sa datim pragom, prolazimo našu strukturu podaci u korisnički prostor preko tabele događaji, nakon čega brišemo unos iz p.
U python skripti koja će učitati ovaj kod, moramo zamijeniti MIN_US i FACTOR pragovima kašnjenja i vremenskim jedinicama, koje ćemo proći kroz argumente:
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"
Sada treba da pripremimo BPF program putem i registrirajte uzorke:
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")
Takođe ćemo morati da utvrdimo struct data_t u našoj skripti, inače nećemo moći ništa čitati:
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)]
Zadnji korak je izlaz podataka na 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()
Sama skripta je dostupna na . Pokušajmo ga pokrenuti na testnoj platformi gdje fio radi, piše u bcache i pozovimo udevadm monitor:
Konačno! Sada vidimo da je ono što je izgledalo kao bcache uređaj sa odugovlačenjem zapravo poziv koji odgađa generic_make_request() za keširani disk.
Kopajte po kernelu
Šta se tačno usporava tokom prenosa zahteva? Vidimo da kašnjenje nastaje i prije početka obračuna zahtjeva, tj. obračun konkretnog zahtjeva za dalji izlaz statistike o njemu (/proc/diskstats ili iostat) još nije počeo. Ovo se lako može provjeriti pokretanjem iostata dok se reproducira problem, ili , koji se zasniva na početku i kraju obračuna zahtjeva. Nijedan od ovih uslužnih programa neće pokazati probleme za zahtjeve na keširani disk.
Ako pogledamo funkciju generic_make_request(), tada ćemo vidjeti da se prije nego što zahtjev započne obračun, pozivaju još dvije funkcije. Prvo - generic_make_request_checks(), vrši provjere legitimnosti zahtjeva u vezi s postavkama diska. Sekunda - , koji ima zanimljiv izazov :
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));
U njemu kernel čeka da se red odmrzne. Hajde da izmerimo kašnjenje 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 | |
Čini se da smo blizu rješenja. Funkcije koje se koriste za zamrzavanje/odmrzavanje reda su и . Koriste se kada je potrebno promijeniti postavke reda zahtjeva, koje su potencijalno opasne za zahtjeve u ovom redu. Prilikom poziva blk_mq_freeze_queue() funkcija brojač se povećava q->mq_depth_freeze. Nakon toga, kernel čeka da se red isprazni .
Vrijeme potrebno za brisanje ovog reda je ekvivalentno latenciji diska jer kernel čeka da se sve operacije u redu dovrše. Nakon što je red prazan, promjene postavki se primjenjuju. Nakon čega se zove , smanjenje brojača freeze_depth.
Sada znamo dovoljno da ispravimo situaciju. Udevadm trigger komanda uzrokuje primjenu postavki za blok uređaj. Ove postavke su opisane u udev pravilima. Možemo otkriti koje postavke zamrzavaju red pokušaja da ih promijenimo putem sysfs-a ili gledanjem u izvorni kod kernela. Također možemo isprobati BCC uslužni program , koji će prikazati tragove steka kernela i korisničkog prostora za svaki poziv terminalu blk_freeze_queue, na primjer:
~# /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]
Udev pravila se mijenjaju prilično rijetko i obično se to dešava na kontroliran način. Dakle, vidimo da čak i primjena već postavljenih vrijednosti uzrokuje porast kašnjenja u prijenosu zahtjeva iz aplikacije na disk. Naravno, generiranje udev događaja kada nema promjena u konfiguraciji diska (na primjer, uređaj nije montiran/isključen) nije dobra praksa. Međutim, možemo pomoći kernelu da ne radi nepotreban posao i zamrzne red zahtjeva ako to nije potrebno. ispraviti situaciju.
zaključak
eBPF je vrlo fleksibilan i moćan alat. U članku smo pogledali jedan praktični slučaj i pokazali mali dio onoga što se može učiniti. Ako ste zainteresirani za razvoj BCC uslužnih programa, vrijedi ih pogledati , koji dobro opisuje osnove.
Postoje i drugi zanimljivi alati za otklanjanje grešaka i profilisanje zasnovani na eBPF-u. Jedan od njih - , koji vam omogućava da pišete moćne jednostruke i male programe na jeziku sličnom awk-u. drugi - , omogućava vam da prikupljate metrike niske razine, visoke rezolucije direktno na vaš prometheus server, uz mogućnost da kasnije dobijete prekrasne vizualizacije, pa čak i upozorenja.
izvor: www.habr.com