В Linux Postoji velik broj alata za otklanjanje pogrešaka u kernelima i aplikacijama. Većina njih negativno utječe na performanse aplikacija i ne može se koristiti u produkciji.
Prije par godina bilo je - eBPF. Omogućuje praćenje kernela i korisničkih aplikacija uz niske troškove i bez potrebe za ponovnom izgradnjom programa i učitavanjem modula trećih strana u kernel.
Već postoji mnogo pomoćnih programa koji koriste eBPF, au ovom ćemo članku pogledati kako napisati vlastiti uslužni program za profiliranje na temelju biblioteke . Članak se temelji na stvarnim događajima. Ići ćemo od problema do rješenja kako bismo pokazali kako se postojeći uslužni programi mogu koristiti u određenim situacijama.
Ceph je spor
Novi host je dodan Ceph klasteru. Nakon što smo premjestili neke od podataka na njega, primijetili smo da je brzina obrade zahtjeva za pisanje puno niža nego na drugim poslužiteljima.
Za razliku od drugih platformi, ovaj host je koristio bcache i novi kernel Linuxa 4.15. Ovo je bio prvi put da je host ove konfiguracije korišten ovdje. I u tom trenutku bilo je jasno da bi korijen problema teoretski mogao biti bilo što.
Istraživanje domaćina
Započnimo gledajući što se događa unutar ceph-osd procesa. Za ovo ćemo koristiti и (više o čemu možete pročitati ):
Slika nam govori da funkcija fdatasync() potrošio puno vremena na slanje zahtjeva funkcijama generic_make_request(). To znači da je najvjerojatnije uzrok problema negdje izvan samog osd daemona. To može biti kernel ili diskovi. Izlaz iostata pokazao je veliku latenciju u obradi zahtjeva od strane bcache diskova.
Prilikom provjere hosta otkrili smo da demon systemd-udevd troši veliku količinu CPU vremena - oko 20% na nekoliko jezgri. Ovo je čudno ponašanje, pa morate saznati zašto. Budući da Systemd-udevd radi s ueventima, odlučili smo ih promotriti udevadm monitor. Ispada da je veliki broj događaja promjene generiran za svaki blok uređaj u sustavu. Ovo je prilično neobično, pa ćemo morati pogledati što generira sve te događaje.
Korištenje BCC alata
Kao što smo već saznali, kernel (i ceph demon u pozivu sustava) provodi puno vremena u generic_make_request(). Pokušajmo izmjeriti brzinu ove funkcije. U Već postoji prekrasan uslužni program - funklatentnost. Pratit ćemo demona prema njegovom PID-u s intervalom od 1 sekunde između izlaza i ispisati rezultat u milisekundama.
Ova značajka obično radi brzo. Sve što radi je prosljeđivanje zahtjeva u red čekanja upravljačkog programa uređaja.
Bcache je složeni uređaj koji se zapravo sastoji od tri diska:
- uređaj za pozadinu (predmemorirani disk), u ovom slučaju to je spori HDD;
- uređaj za predmemoriju (disk za predmemoriju), ovdje je ovo jedna particija NVMe uređaja;
- bcache virtualni uređaj s kojim se aplikacija pokreće.
Znamo da je prijenos zahtjeva spor, ali za koji od ovih uređaja? Time ćemo se pozabaviti malo kasnije.
Sada znamo da će događaji vjerojatno izazvati probleme. Pronaći što točno uzrokuje njihovu generaciju nije tako lako. Pretpostavimo da je ovo neka vrsta softvera koji se povremeno pokreće. Pogledajmo kakav softver radi na sustavu pomoću skripte 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 puni rezultat execsnoopa, ali jedan redak koji nas je zanimao izgledao 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. Pokazalo se da je proces s PID-om 5802 jedna od niti našeg sustava nadzora. Prilikom provjere konfiguracije sustava 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 dulji, otkrili smo da se latencija obrade zahtjeva na ovom hostu više ne ističe u usporedbi s drugim hostovima.
Ali još uvijek nije jasno zašto je bcache uređaj bio tako spor. Pripremili smo testnu platformu s identičnom konfiguracijom i pokušali reproducirati problem pokretanjem fio na bcacheu, povremeno pokretanjem udevadm okidača za generiranje uevenata.
Pisanje BCC alata
Pokušajmo napisati jednostavan pomoćni program za praćenje i prikaz najsporijih poziva generic_make_request(). Također nas zanima naziv pogona za koji je ova funkcija pozvana.
Plan je jednostavan:
- Registar kprobe na generic_make_request():
- Ime diska spremamo u memoriju, dostupnom kroz argument funkcije;
- Spremamo vremensku oznaku.
- Registar kretprobe za povratak iz generic_make_request():
- Dobivamo trenutnu vremensku oznaku;
- Tražimo spremljenu vremensku oznaku i uspoređujemo je s trenutnom;
- Ako je rezultat veći od navedenog, tada pronalazimo naziv spremljenog diska i prikazujemo ga na terminalu.
Kprobe и kretprobes koristite mehanizam prijelomne točke za promjenu koda funkcije u hodu. Možeš č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 parsiranje 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, eBPF programi koriste . Mi ćemo učiniti isto. Koristit ćemo PID procesa kao ključ, a definirati strukturu kao vrijednost:
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 registriramo hash tablicu tzv p, s vrstom ključa u64 i vrijednost tipa struct data_t. Tablica će biti dostupna u kontekstu našeg BPF programa. Makro BPF_PERF_OUTPUT registrira drugu tablicu tzv događaji, koji se koristi za u korisnički prostor.
Kada mjerite kašnjenja između pozivanja funkcije i povratka s 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 izmjeriti kašnjenje između pozivanja funkcije u kontekstu jednog procesa i povratka s te funkcije u kontekstu drugog procesa, ali to je vjerojatno beskorisno. Ovdje bi dobar primjer bio , gdje je ključ hash tablice postavljen na pokazivač na struct zahtjev, što 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 drugim argumentom . Nakon toga dobivamo PID procesa u čijem kontekstu radimo, te trenutnu vremensku oznaku u nanosekundama. Sve to zapisujemo u svježe odabrano struct data_t podaci. Ime diska dobivamo iz strukture bio, koji se prenosi prilikom poziva generic_make_request(), i spremite ga u istu strukturu datum. Zadnji korak je dodavanje unosa u hash tablicu koja je ranije spomenuta.
Sljedeća funkcija bit će pozvana po povratku s 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 je funkcija slična prethodnoj: saznajemo PID procesa i vremensku oznaku, ali ne dodjeljujemo memoriju za novu strukturu podataka. Umjesto toga, pretražujemo hash tablicu za već postojeću strukturu koristeći ključ == trenutni PID. Ako je struktura pronađena, tada saznajemo naziv pokrenutog procesa i dodajemo mu ga.
Binarni pomak koji ovdje koristimo potreban je za dobivanje GID-a niti. oni. PID glavnog procesa koji je pokrenuo nit u čijem kontekstu radimo. Funkcija koju pozivamo vraća i GID i PID niti u jednoj 64-bitnoj vrijednosti.
Kod izlaza na terminal trenutno nas ne zanima nit, ali nas zanima glavni proces. Nakon usporedbe dobivenog kašnjenja s danim pragom, prosljeđujemo našu strukturu datum u korisnički prostor putem tablice događaji, nakon čega brišemo unos iz p.
U python skripti koja će učitati ovaj kod, moramo zamijeniti MIN_US i FACTOR s pragovima kašnjenja i vremenskim jedinicama, koje ćemo proslijediti 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 moramo pripremiti 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đer ćemo morati odrediti struct data_t u našoj skripti, inače nećemo moći ništa proč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 dostupna je na . Pokušajmo to pokrenuti na testnoj platformi na kojoj se izvodi fio, piše u bcache i poziva udevadm monitor:
Konačno! Sada vidimo da je ono što je izgledalo kao zastoj bcache uređaja zapravo zastoj poziva generic_make_request() za predmemorirani disk.
Kopajte po kernelu
Što se točno usporava tijekom prijenosa zahtjeva? Vidimo da do kašnjenja dolazi i prije početka obračuna zahtjeva, tj. obračun specifičnog zahtjeva za daljnji izlaz statistike na njemu (/proc/diskstats ili iostat) još nije započeo. To se može lako provjeriti pokretanjem iostata tijekom reprodukcije problema, ili , koji se temelji na početku i kraju obračuna zahtjeva. Niti jedan od ovih uslužnih programa neće pokazati probleme za zahtjeve za predmemorirani disk.
Ako pogledamo funkciju generic_make_request(), tada ćemo vidjeti da se prije početka obračuna zahtjeva pozivaju još dvije funkcije. Prvo - generic_make_request_checks(), vrši provjeru legitimnosti zahtjeva u vezi postavki diska. drugo - , 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 čekanja odmrzne. Izmjerimo 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 čekanja. Prilikom poziva blk_mq_freeze_queue() funkcija brojač se povećava q->mq_dubina_smrzavanja. Nakon toga, kernel čeka da se red čekanja isprazni .
Vrijeme potrebno za brisanje ovog reda čekanja je ekvivalentno kašnjenju diska jer kernel čeka da se sve operacije u redu čekanja završe. Nakon što je red čekanja prazan, promjene postavki se primjenjuju. Nakon čega se zove , smanjivanje brojača dubina_smrzavanja.
Sada znamo dovoljno da ispravimo situaciju. Naredba okidača udevadm uzrokuje primjenu postavki za blok uređaj. Ove postavke su opisane u udev pravilima. Možemo pronaći koje postavke zamrzavaju red čekanja ako ih pokušamo promijeniti kroz sysfs ili gledajući izvorni kod kernela. Također možemo isprobati pomoćni program BCC , koji će ispisati tragove steka jezgre i korisničkog prostora za svaki poziv terminalu blk_red_za_zamrzavanje, 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 vrlo rijetko i obično se to događa na kontrolirani način. Dakle, vidimo da čak i primjena već postavljenih vrijednosti uzrokuje skok 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/odspojen) nije dobra praksa. Međutim, možemo pomoći kernelu da ne radi nepotreban posao i zamrznuti red zahtjeva ako to nije potrebno. ispraviti situaciju.
Zaključak
eBPF je vrlo fleksibilan i moćan alat. U članku smo pogledali jedan praktičan slučaj i pokazali mali dio onoga što se može učiniti. Ako ste zainteresirani za razvoj BCC pomoćnih programa, vrijedi pogledati , koji dobro opisuje osnove.
Postoje i drugi zanimljivi alati za ispravljanje pogrešaka i profiliranje temeljeni na eBPF-u. Jedan od njih - , koji vam omogućuje da pišete moćne jednolinijske programe i male programe na jeziku sličnom awk-u. drugi - , omogućuje vam prikupljanje metrika niske razine visoke razlučivosti izravno u vaš prometheus poslužitelj, uz mogućnost kasnijeg dobivanja prekrasnih vizualizacija, pa čak i upozorenja.
Izvor: www.habr.com
