Det finns mÄnga verktyg för att debugga kÀrnor och applikationer i Linux. De flesta av dem pÄverkar applikationers prestanda negativt och kan inte anvÀndas i produktion.
För ett par Ă„r sedan skapades â eBPF. Det gör det möjligt att spĂ„ra kĂ€rnan och anvĂ€ndarapplikationer med lĂ„g overhead och utan behov av att Ă„terkompilera program eller ladda externa moduler i kĂ€rnan.
Idag finns det redan mÄnga applikationsverktyg som anvÀnder eBPF, och i den hÀr artikeln kommer vi att titta pÄ hur man skriver ett eget profileringsverktyg baserat pÄ biblioteket . Artikeln baseras pÄ verkliga hÀndelser. Vi kommer att gÄ frÄn problemets uppkomst till dess lösning för att visa hur redan existerande verktyg kan anvÀndas i specifika situationer.
Ceph Àr lÄngsam
En ny vÀrd har lagts till i Ceph-klustret. Efter migrering av delar av data till den mÀrkte vi att hastigheten pÄ skrivbegÀrningar var mycket lÀgre Àn pÄ andra servrar.
Till skillnad frÄn andra plattformar anvÀndes bcache och en ny kÀrna linux 4.15 pÄ denna vÀrd. Denna konfiguration anvÀndes hÀr för första gÄngen. Och vid den tidpunkten var det klart att orsaken till problemet teoretiskt kunde vara vad som helst.
Undersöker vÀrden
Vi börjar med att titta pÄ vad som hÀnder inuti processen ceph-osd. För detta kommer vi att anvÀnda och (mer om det kan lÀsas ):
Bilden visar att funktionen fdatasync() tog mycket tid nÀr en begÀran skickades i funktionen generic_make_request(). Det betyder att orsaken till problemen troligen ligger nÄgonstans utanför sjÀlva osd-demonen. Detta kan vara antingen kÀrnan eller diskarna. Utfallet av iostat visade hög fördröjning i hanteringen av begÀrningar frÄn bcache-diskarna.
Vid kontroll av vĂ€rden upptĂ€ckte vi att demon systemd-udevd förbrukade mycket CPU-tid â cirka 20% pĂ„ flera kĂ€rnor. Detta Ă€r ett mĂ€rkligt beteende, sĂ„ vi mĂ„ste ta reda pĂ„ orsaken. Eftersom Systemd-udevd arbetar med uevent, bestĂ€mde vi oss för att titta pĂ„ dem via udevadm monitor. Det visade sig att en stor mĂ€ngd change-hĂ€ndelser genererades för varje blockenhet i systemet. Detta Ă€r ganska ovanligt, sĂ„ vi mĂ„ste undersöka vad som orsakar alla dessa hĂ€ndelser.
AnvÀnder BCC-verktyget
Som vi redan har bekrĂ€ftat spenderar kĂ€rnan (och demon ceph i systemanropet) mycket tid pĂ„ generic_make_request(). LĂ„t oss försöka mĂ€ta hastigheten pĂ„ denna funktion. I finns redan ett utmĂ€rkt verktyg â funclatency. Vi kommer att spĂ„ra demon via dess PID med en intervall pĂ„ 1 sekund mellan informationsutskrifter och visa resultatet i millisekunder.
Normalt fungerar denna funktion snabbt. Allt den gör Àr att skicka en begÀran till enhetsdrivrutins kö.
Bcache Àr en komplex enhet som faktiskt bestÄr av tre diskar:
- backing device (cachebar disk), i detta fall en lÄngsam HDD;
- caching device (cacheminne), hÀr Àr det en partition av NVMe-enheten;
- den virtuella enheten bcache, som programmet arbetar med.
Vi vet att överföringen av begÀran saktar ner, men vilket av dessa enheter? Vi kommer att ta reda pÄ det senare.
För nu vet vi att ueventerna sannolikt orsakar problemen. Att hitta vad som exakt utlöser deras generering Àr inte sÄ enkelt. LÄt oss anta att det Àr nÄgon mjukvara som körs periodiskt. Vi ska se vilken mjukvara som startas i systemet med hjÀlp av skriptet execsnoop frÄn samma . Vi kör det och dirigerar utdata till en fil.
Till exempel sÄ hÀr:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Vi kommer inte att visa hela utskriften av execsnoop hÀr, men en intressant rad sÄg ut sÄ hÀr:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:\/]' '{print $2}' | sed 's\/^ ([0-9]*) C.*\/1\/'
Den tredje kolumnen Àr PPID (parent PID) för processen. Processen med PID 5802 visade sig vara en av trÄdarna i vÄrt övervakningssystem. Vid kontroll av konfigurationen av övervakningssystemet upptÀcktes felaktigt angivna parametrar. Temperaturen pÄ HBA-adaptern mÀttes var 30:e sekund, vilket var mycket oftare Àn nödvÀndigt. Efter att ha Àndrat kontrollintervallet till ett lÀngre, upptÀckte vi att fördröjningen i begÀrningsbehandlingen pÄ denna vÀrd inte lÀngre stack ut i förhÄllande till andra vÀrdar.
Men det Àr fortfarande oklart varför bcache-enheten var sÄ seg. Vi förberedde en testplattform med identisk konfiguration och försökte reproducera problemet genom att köra fio pÄ bcache och periodiskt starta udevadm trigger för att generera uevents.
Skriver BCC-baserade verktyg
LÄt oss försöka skriva ett enkelt verktyg för att spÄra och visa de lÄngsammaste anropen generic_make_request(). Vi Àr ocksÄ intresserade av namnet pÄ disken för vilken denna funktion utfördes.
Planen Àr enkel:
- Registrera kprobe till generic_make_request():
- Vi sparar namnet pÄ disken i minnet, tillgÀngligt via funktionsargumentet;
- Vi sparar tidsstÀmpeln.
- Registrera kretprobe pÄ ÄtervÀndo frÄn generic_make_request():
- HÀmtar den aktuella tidsstÀmpeln;
- Söker efter en sparad tidsstÀmpel och jÀmför med den aktuella;
- Om resultatet Àr större Àn det angivna, söker vi efter det sparade disknamnet och skriver ut det i terminalen.
Kprobes och kretprobes anvÀnder ett mekanism av stoppunkter för att Àndra funktionskod pÄ flygande. Du kan lÀsa och artikel om detta Àmne. Om vi tittar pÄ koden för olika verktyg i , kan vi mÀrka att de har en identisk struktur. SÄ vi kommer att hoppa över att parsa skriptargument och gÄ direkt till BPF-programmet.
Texten eBPF i python-skriptet ser ut som följer:
bpf_text = ''' # HĂ€r kommer bpf-programkod att vara '''
För att utbyta data mellan funktioner anvÀnder eBPF-program . LÄt oss göra samma sak. Som nyckel kommer vi att anvÀnda PID för processen, och som vÀrde definierar vi strukturen:
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);
HÀr registrerar vi en hash-tabell som kallas p, med nyckeltyp u64 och vÀrdetyp struct data_t. Tabellen kommer att vara tillgÀnglig i kontexten för vÄrt BPF-program. Makrot BPF_PERF_OUTPUT registrerar en annan tabell som kallas events, vilket anvÀnds för till anvÀndarutrymmet.
NÀr man mÀter fördröjningar mellan funktionsanrop och ÄtervÀndande frÄn den, eller mellan anrop av olika funktioner, mÄste man ta hÀnsyn till att de erhÄllna uppgifterna mÄste tillhöra samma kontext. Med andra ord, man mÄste komma ihÄg den möjliga parallella körningen av funktioner. Vi har möjlighet att mÀta fördröjningen mellan anropet av en funktion i kontexten för en process och ÄtervÀndandet frÄn denna funktion i kontexten för en annan process, men detta Àr förmodligen meningslöst. Ett bra exempel hÀr kan vara , dÀr nyckeln till hash-tabellen stÀlls in som en pekare pÄ struct request, vilket speglar en begÀran till disken.
DÀrefter behöver vi skriva kod som körs nÀr den undersökta funktionen anropas:
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);
}
HÀr kommer den andra argumentet att sÀttas in som den första argumentet i den anropade funktionen . Efter detta fÄr vi PID-processen som vi arbetar i samt den aktuella tidsstÀmpeln i nanosekunder. Vi skriver ner allt detta i den nyutdelade struct data_t data. Diskens namn fÄr vi frÄn strukturen bio, som skickas vid anropet generic_make_request(), och sparar det i samma struktur data. Det sista steget Àr att lÀgga till en post i hash-tabellen som nÀmndes tidigare.
Den nÀsta funktionen kommer att anropas vid ÄtergÄng frÄn 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);
}
}
Denna funktion liknar den föregÄende: vi tar reda pÄ PID-processen och tidsstÀmpeln, men allokerar inte minne för en ny data-struktur. IstÀllet letar vi upp den redan existerande strukturen i hash-tabellen med nyckeln == nuvarande PID. Om strukturen hittas fÄr vi reda pÄ namnet pÄ den körda processen och lÀgger till det i den.
Den binÀra skiftningen vi anvÀnder hÀr behövs för att fÄ trÄd GID, d.v.s. PID för huvudprocessen som startade trÄden, i sammanhanget vi arbetar. Den funktion vi anropar ÄtervÀnder bÄde GID för trÄden och dess PID i ett enda 64-bitars vÀrde.
Vid utskrift till terminalen Àr vi för nÀrvarande inte intresserade av trÄden, utan av huvudprocessen. Efter att ha jÀmfört den erhÄllna latensen med den angivna tröskeln, överför vi vÄr struktur data till anvÀndarrummet genom tabellen events, varefter vi tar bort posten frÄn p.
I python-skriptet som kommer att ladda denna kod behöver vi ersÀtta MIN_US och FACTOR med latensgrÀnser och tidsenheter som vi kommer att vidarebefordra genom argument:
bpf_text = bpf_text.replace('MIN_US',str(min_usec))
if args.milliseconds:
bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;')
label = "msek"
else:
bpf_text = bpf_text.replace('FACTOR','')
label = "mikrosek"
Nu mÄste vi förbereda BPF-programmet genom och registrera probes:
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")
Vi mÄste Àven definiera struct data_t i vÄrt skript, annars kommer inget att kunna lÀsas:
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)]
Det sista steget Àr att skriva ut data pÄ terminalen:
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)
# formatera utdata
start = 0
while 1:
try:
b.perf_buffer_poll()
except KeyboardInterrupt:
exit()
SjÀlva skriptet finns pÄ . LÄt oss försöka köra det pÄ en testplattform dÀr fio körs och skriver till bcache, och köra udevadm monitor:
Ăntligen! Nu ser vi att det som sĂ„g ut som ett bcache-enhet som saktade ner egentligen Ă€r ett saktande anrop generic_make_request() för den cachade disken.
GrÀv i kÀrnan
Vad exakt orsakar fördröjning under begÀrans överföring? Vi ser att fördröjningen intrÀffar Àven innan begÀrans redovisning börjar, det vill sÀga redovisningen av den specifika begÀran för vidare statistik ( /proc/diskstats eller iostat) har Ànnu inte börjat. Detta kan enkelt verifieras genom att köra iostat medan problemet reproduceras, eller , som baseras pÄ början och slutet av begÀrans redovisning. Ingen av dessa verktyg kommer att visa nÄgra problem för begÀrningar till den cachade disken.
Om vi ser pÄ funktionen generic_make_request(), kommer vi att se att innan begÀrans redovisning börjar anropas ytterligare tvÄ funktioner. Den första Àr generic_make_request_checks(), som utför legitimitetskontroller av begÀran i förhÄllande till diskens instÀllningar. Den andra Àr , dÀr det finns ett intressant anrop :
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));
KÀrnan vÀntar pÄ att köa ska avfrysas. LÄt oss mÀta fördröjningen blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
SpÄrar 1 funktioner för "blk_queue_enter"... Tryck Ctrl-C för att avsluta.
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 | |
Det verkar som att vi Àr nÀra en lösning. Funktionerna som anvÀnds för att "frysa/avfrosta" kön Àr och . De anvÀnds nÀr det Àr nödvÀndigt att förÀndra köinstÀllningar som potentiellt kan vara farliga för begÀrningar som redan finns i denna kö. Vid anropet blk_mq_freeze_queue() anropas av funktionen rÀknaren inkrementeras q->mq_freeze_depth. Efter detta vÀntar kÀrnan pÄ att köen ska tömmas i .
Tiden för att rensa denna kö Àr ekvivalent med diskens fördröjning, eftersom kÀrnan vÀntar pÄ att alla schemalagda operationer ska slutföras. SÄ snart kön Àr tom tillÀmpas instÀllningarna. DÀrefter anropas , vilket minskar rÀknaren freeze_depth.
Nu vet vi tillrÀckligt för att ÄtgÀrda situationen. Kommandot udevadm trigger resulterar i att instÀllningarna för det blockenheten tillÀmpas. Dessa instÀllningar beskrivs i udev-regler. Vi kan ta reda pÄ vilka instÀllningar som "fryser" kön genom att försöka Àndra dem via sysfs eller genom att titta pÄ kÀrnans kÀllkod. Vi kan ocksÄ försöka med verktyget BCC , som kommer att visa stacktraces frÄn kÀrnan och anvÀndarrummet för varje anrop av blk_freeze_queue, till exempel:
~# /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-regler Àndras ganska sÀllan och vanligtvis sker detta under kontroll. SÄ vi ser att Àven tillÀmpningen av redan angivna vÀrden orsakar en ökning av fördröjningen för begÀran frÄn applikationen till disken. Naturligtvis Àr det ingen bra praxis att generera udev-hÀndelser nÀr det inte finns nÄgra Àndringar i diskens konfiguration (till exempel nÀr en enhet inte kopplas in/ur), men vi kan hjÀlpa kÀrnan att undvika onödig arbetsbelastning och att inte "frysa" begÀrningskön om det inte finns nÄgot behov. rÀttar till situationen.
Slutsats
eBPF Àr ett mycket flexibelt och kraftfullt verktyg. I artikeln har vi gÄtt igenom ett praktiskt fall och visat en liten del av vad som Àr möjligt att göra. Om du Àr intresserad av att utveckla BCC-verktyg kan det vara vÀrt att titta pÄ , som bra beskriver grunderna i hur det fungerar.
Det finns ocksÄ andra intressanta verktyg för felsökning och profilering som bygger pÄ eBPF. Ett av dem Àr , som möjliggör att skriva kraftfulla enradare och smÄ program i ett awk-liknande sprÄk. Ett annat Àr , som gör det möjligt att samla in lÄg-nivÄ högupplösta metrik direkt till din Prometheus-server, med möjligheten att i framtiden fÄ vacker visualisering och till och med larm.
KĂ€lla: habr.com
