Linux má veľké množstvo nástrojov na ladenie jadra a aplikácií. Väčšina z nich má negatívny vplyv na výkon aplikácie a nie je možné ich použiť vo výrobe.
Pred pár rokmi tam bolo — eBPF. Umožňuje sledovať jadro a používateľské aplikácie s nízkou réžiou a bez potreby prestavby programov a načítania modulov tretích strán do jadra.
Už existuje veľa aplikačných utilít, ktoré používajú eBPF, a v tomto článku sa pozrieme na to, ako napísať vlastný profilovací nástroj založený na knižnici . Článok je založený na skutočných udalostiach. Pôjdeme od problému k vyriešeniu, aby sme ukázali, ako možno existujúce nástroje použiť v konkrétnych situáciách.
Ceph je pomalý
Do klastra Ceph bol pridaný nový hostiteľ. Po migrácii niektorých údajov naň sme si všimli, že rýchlosť spracovania požiadaviek na zápis bola oveľa nižšia ako na iných serveroch.
Na rozdiel od iných platforiem tento hostiteľ používal bcache a nové jadro linuxu 4.15. Toto bolo prvýkrát, čo sa tu použila hostiteľská konfigurácia. A v tej chvíli bolo jasné, že koreňom problému môže byť teoreticky čokoľvek.
Skúmanie hostiteľa
Začnime tým, že sa pozrieme na to, čo sa deje vo vnútri procesu ceph-osd. Na to použijeme и (viac o tom si môžete prečítať ):
Obrázok nám hovorí, že funkcia fdatasync() strávil veľa času odosielaním požiadavky na funkcie generic_make_request(). To znamená, že s najväčšou pravdepodobnosťou je príčina problémov niekde mimo samotného démona osd. Môže to byť buď jadro alebo disky. Výstup iostatu vykazoval vysokú latenciu pri spracovaní požiadaviek diskmi bcache.
Pri kontrole hostiteľa sme zistili, že démon systemd-udevd spotrebúva veľké množstvo procesorového času – asi 20 % na niekoľkých jadrách. Toto je zvláštne správanie, takže musíte zistiť prečo. Keďže Systemd-udevd pracuje s udalosťami, rozhodli sme sa na ne pozrieť monitor udevadm. Ukázalo sa, že pre každé blokové zariadenie v systéme bolo vygenerované veľké množstvo udalostí zmien. To je dosť nezvyčajné, takže sa budeme musieť pozrieť na to, čo generuje všetky tieto udalosti.
Používanie BCC Toolkit
Ako sme už zistili, jadro (a démon ceph v systémovom volaní) trávi veľa času v generic_make_request(). Skúsme zmerať rýchlosť tejto funkcie. IN Už existuje úžasná pomôcka - funkcionality. Démona budeme sledovať podľa jeho PID s 1 sekundovým intervalom medzi výstupmi a výsledok vypíšeme v milisekundách.
Táto funkcia zvyčajne funguje rýchlo. Všetko, čo robí, je odoslanie požiadavky do frontu ovládačov zariadenia.
Bcache je komplexné zariadenie, ktoré sa v skutočnosti skladá z troch diskov:
- záložné zariadenie (disk vo vyrovnávacej pamäti), v tomto prípade ide o pomalý HDD;
- cachovacie zariadenie (caching disk), tu je to jeden oddiel zariadenia NVMe;
- virtuálne zariadenie bcache, s ktorým aplikácia beží.
Vieme, že prenos žiadosti je pomalý, ale pre ktoré z týchto zariadení? Budeme sa tým zaoberať trochu neskôr.
Teraz vieme, že udalosti pravdepodobne spôsobia problémy. Nájsť, čo presne spôsobuje ich generáciu, nie je také jednoduché. Predpokladajme, že ide o nejaký druh softvéru, ktorý sa spúšťa pravidelne. Pozrime sa, aký druh softvéru beží v systéme pomocou skriptu execsnoop z toho istého . Spustíme to a odošleme výstup do súboru.
Napríklad takto:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nebudeme tu ukazovať úplný výstup execsnoopu, ale jeden riadok, ktorý nás zaujíma, vyzeral takto:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Tretí stĺpec je PPID (rodičovský PID) procesu. Proces s PID 5802 sa ukázal byť jedným z vlákien nášho monitorovacieho systému. Pri kontrole konfigurácie monitorovacieho systému boli zistené chybné parametre. Teplota adaptéra HBA sa merala každých 30 sekúnd, čo je oveľa častejšie, ako je potrebné. Po zmene intervalu kontroly na dlhší sme zistili, že latencia spracovania požiadaviek na tomto hostiteľovi už nevyniká v porovnaní s inými hostiteľmi.
Stále však nie je jasné, prečo bolo zariadenie bcache také pomalé. Pripravili sme testovaciu platformu s identickou konfiguráciou a pokúsili sme sa problém reprodukovať spustením fio na bcache, pričom pravidelne spúšťame spúšťač udevadm na generovanie udalostí.
Nástroje na písanie BCC
Skúsme napísať jednoduchú utilitu na sledovanie a zobrazenie najpomalších hovorov generic_make_request(). Zaujíma nás aj názov disku, pre ktorý bola táto funkcia volaná.
Plán je jednoduchý:
- Registrujeme sa ksonda na generic_make_request():
- Názov disku uložíme do pamäte dostupnej cez argument funkcie;
- Časovú pečiatku uložíme.
- Registrujeme sa kretprobe pre návrat z generic_make_request():
- Získame aktuálnu časovú pečiatku;
- Hľadáme uloženú časovú pečiatku a porovnávame ju s aktuálnou;
- Ak je výsledok väčší ako zadaný, nájdeme uložený názov disku a zobrazíme ho na termináli.
Ksondy и kretsondy použite mechanizmus prerušenia na zmenu kódu funkcie za behu. Môžeš čítať и článok na túto tému. Ak sa pozriete na kód rôznych nástrojov v , potom môžete vidieť, že majú identickú štruktúru. V tomto článku teda preskočíme analýzu argumentov skriptu a prejdeme k samotnému programu BPF.
Text eBPF vo vnútri python skriptu vyzerá takto:
bpf_text = “”” # Here will be the bpf program code “””
Na výmenu údajov medzi funkciami používajú programy eBPF . Urobíme to isté. Ako kľúč použijeme proces PID a štruktúru definujeme ako hodnotu:
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);
Tu registrujeme hašovaciu tabuľku tzv p, s typom kľúča u64 a hodnotu typu struct data_t. Tabuľka bude dostupná v kontexte nášho programu BPF. Makro BPF_PERF_OUTPUT registruje ďalšiu tabuľku s názvom akcie, ktorý sa používa na do užívateľského priestoru.
Pri meraní oneskorení medzi volaním funkcie a návratom z nej alebo medzi volaniami rôznych funkcií je potrebné vziať do úvahy, že prijaté dáta musia patriť do rovnakého kontextu. Inými slovami, musíte pamätať na možné paralelné spustenie funkcií. Máme schopnosť merať latenciu medzi volaním funkcie v kontexte jedného procesu a návratom z tejto funkcie v kontexte iného procesu, ale je to pravdepodobne zbytočné. Tu by bol dobrý príklad , kde je kľúč hašovacej tabuľky nastavený na ukazovateľ žiadosť o štruktúru, ktorý odráža jednu požiadavku na disk.
Ďalej musíme napísať kód, ktorý sa spustí, keď sa zavolá skúmaná funkcia:
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);
}
Tu bude prvý argument volanej funkcie nahradený ako druhý argument . Potom dostaneme PID procesu, v kontexte ktorého pracujeme, a aktuálnu časovú pečiatku v nanosekundách. Všetko to zapisujeme do čerstvo vybraného struct data_t data. Názov disku získame zo štruktúry bio, ktorý sa odovzdáva pri volaní generic_make_request()a uložte ho v rovnakej štruktúre data. Posledným krokom je pridanie položky do hašovacej tabuľky, ktorá bola spomenutá vyššie.
Nasledujúca funkcia sa zavolá pri návrate z 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);
}
}
Táto funkcia je podobná predchádzajúcej: zistíme PID procesu a časovú pečiatku, ale nevyčleníme pamäť pre novú dátovú štruktúru. Namiesto toho hľadáme v hašovacej tabuľke už existujúcu štruktúru pomocou kľúča == aktuálny PID. Ak sa štruktúra nájde, tak zistíme názov bežiaceho procesu a pridáme ho doň.
Binárny posun, ktorý tu používame, je potrebný na získanie GID vlákna. tie. PID hlavného procesu, ktorý spustil vlákno, v kontexte ktorého pracujeme. Funkcia, ktorú voláme vráti GID vlákna aj jeho PID v jednej 64-bitovej hodnote.
Pri výstupe na terminál nás momentálne nezaujíma vlákno, ale zaujíma nás hlavný proces. Po porovnaní výsledného oneskorenia s daným prahom prejdeme našou štruktúrou data do užívateľského priestoru cez tabuľku akcie, po ktorom vymažeme záznam z p.
V python skripte, ktorý načíta tento kód, musíme nahradiť MIN_US a FACTOR prahovými hodnotami oneskorenia a časovými jednotkami, ktoré prejdeme cez argumenty:
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"
Teraz musíme pripraviť program BPF cez a zaregistrovať vzorky:
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")
Budeme musieť tiež určiť struct data_t v našom skripte, inak nebudeme môcť nič prečítať:
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)]
Posledným krokom je výstup údajov do terminálu:
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()
Samotný skript je dostupný na . Skúsme to spustiť na testovacej platforme, kde beží fio, zapisuje do bcache a zavoláme udevadm monitor:
Konečne! Teraz vidíme, že to, čo vyzeralo ako blokujúce zariadenie bcache, je v skutočnosti blokujúce volanie generic_make_request() pre disk s vyrovnávacou pamäťou.
Kopať do jadra
Čo presne sa spomaľuje počas prenosu požiadavky? Vidíme, že omeškanie nastáva ešte pred začatím účtovania požiadavky, t.j. účtovanie konkrétnej požiadavky na ďalší výstup štatistík o nej (/proc/diskstats alebo iostat) sa ešte nezačalo. Dá sa to jednoducho overiť spustením iostatu pri reprodukovaní problému, príp , ktorá vychádza zo začiatku a konca účtovania požiadavky. Žiadna z týchto pomôcok neukáže problémy s požiadavkami na disk vo vyrovnávacej pamäti.
Ak sa pozrieme na funkciu generic_make_request(), potom uvidíme, že pred spustením účtovania požiadavky sa zavolajú ďalšie dve funkcie. Najprv - generic_make_request_checks(), vykoná kontroly oprávnenosti požiadavky ohľadom nastavenia disku. druhá - , ktorá má zaujímavú výzvu :
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));
V ňom jadro čaká na rozmrazenie frontu. Poďme merať oneskorenie 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 | |
Zdá sa, že sme blízko k riešeniu. Funkcie používané na zmrazenie/rozmrazenie frontu sú и . Používajú sa, keď je potrebné zmeniť nastavenia frontu požiadaviek, ktoré sú potenciálne nebezpečné pre požiadavky v tomto fronte. Pri volaní blk_mq_freeze_queue() funkcie počítadlo sa zvýši q->mq_freeze_depth. Potom jadro čaká, kým sa front nevyprázdni .
Čas potrebný na vyčistenie tohto frontu je ekvivalentný oneskoreniu disku, pretože jadro čaká na dokončenie všetkých operácií vo fronte. Po vyprázdnení frontu sa použijú zmeny nastavení. Po ktorom sa volá , zníženie počítadla freeze_depth.
Teraz vieme dosť na to, aby sme situáciu napravili. Spúšťací príkaz udevadm spôsobí, že sa použijú nastavenia pre blokové zariadenie. Tieto nastavenia sú popísané v pravidlách udev. Ktoré nastavenia zamŕzajú front môžeme zistiť tak, že sa ich pokúsime zmeniť cez sysfs alebo sa pozrieme na zdrojový kód jadra. Vyskúšať môžeme aj utilitu BCC , ktorý vypíše stopy zásobníka jadra a používateľského priestoru pre každé volanie terminálu blk_freeze_queue, napríklad:
~# /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]
Pravidlá Udev sa menia pomerne zriedka a zvyčajne sa to deje kontrolovaným spôsobom. Vidíme teda, že aj použitie už nastavených hodnôt spôsobuje prudký nárast oneskorenia pri prenose požiadavky z aplikácie na disk. Samozrejme, generovanie udalostí udev, keď nedôjde k žiadnym zmenám v konfigurácii disku (napríklad zariadenie nie je pripojené/odpojené), nie je dobrým zvykom. Môžeme však pomôcť jadru nerobiť zbytočnú prácu a zmraziť front žiadostí, ak to nie je potrebné. napraviť situáciu.
záver
eBPF je veľmi flexibilný a výkonný nástroj. V článku sme sa pozreli na jeden praktický prípad a predviedli malú časť toho, čo sa dá urobiť. Ak máte záujem o vývoj nástrojov BCC, stojí za to sa na to pozrieť , ktorý dobre popisuje základy.
Existujú aj ďalšie zaujímavé nástroje na ladenie a profilovanie založené na eBPF. Jeden z nich - , ktorý vám umožňuje písať výkonné jednoduché riadky a malé programy v jazyku podobnom awk. Ďalší - , vám umožňuje zhromažďovať metriky nízkej úrovne vo vysokom rozlíšení priamo na váš server prometheus s možnosťou neskôr získať nádherné vizualizácie a dokonca aj upozornenia.
Zdroj: hab.com