Suurest tsefiidi latentsusest kuni eBPF/BCC-ga kerneli paigani

Suurest tsefiidi latentsusest kuni eBPF/BCC-ga kerneli paigani

Linuxil on palju tööriistu kerneli ja rakenduste silumiseks. Enamikul neist on negatiivne mõju rakenduse jõudlusele ja neid ei saa tootmises kasutada.

Paar aastat tagasi oli on välja töötatud veel üks tööriist - eBPF. See võimaldab jälgida kerneli ja kasutajarakendusi väikese üldkuluga ning ilma vajaduseta programme ümber ehitada ja kolmanda osapoole mooduleid kernelisse laadida.

eBPF-i kasutavad juba palju rakendusutiliite ja selles artiklis vaatleme, kuidas raamatukogu põhjal oma profiilide koostamise utiliiti kirjutada. PythonBCC. Artikkel põhineb tõestisündinud sündmustel. Läheme probleemist lahenduseni, et näidata, kuidas olemasolevaid utiliite saab konkreetsetes olukordades kasutada.

Ceph on aeglane

Ceph-klastrisse on lisatud uus host. Pärast osa andmete sellesse migreerimist märkasime, et selle kirjutamistaotluste töötlemise kiirus oli palju väiksem kui teistel serveritel.

Suurest tsefiidi latentsusest kuni eBPF/BCC-ga kerneli paigani
Erinevalt teistest platvormidest kasutas see host bcache'i ja uut linux 4.15 tuuma. See oli esimene kord, kui siin kasutati selle konfiguratsiooni hosti. Ja sel hetkel oli selge, et probleemi juur võib teoreetiliselt olla ükskõik milline.

Peremehe uurimine

Alustame sellest, mis toimub ceph-osd protsessi sees. Selleks kasutame täiuslik и flamaskoop (mille kohta saate rohkem lugeda siin):

Suurest tsefiidi latentsusest kuni eBPF/BCC-ga kerneli paigani
Pilt ütleb meile, et funktsioon fdatasync() kulutas palju aega funktsioonidele päringu saatmisele generic_make_request(). See tähendab, et suure tõenäosusega on probleemide põhjus kusagil väljaspool osd deemonit ennast. See võib olla kas tuum või kettad. Iostaadi väljund näitas suurt latentsust bcache-ketaste päringute töötlemisel.

Hosti kontrollides avastasime, et systemd-udevd deemon kulutab palju protsessori aega – mitmel tuumal umbes 20%. See on kummaline käitumine, nii et peate välja selgitama, miks. Kuna Systemd-udevd töötab ueventsidega, otsustasime need läbi vaadata udevadm monitor. Selgub, et iga süsteemi plokkseadme jaoks genereeriti suur hulk muudatussündmusi. See on üsna ebatavaline, seega peame vaatama, mis kõik need sündmused genereerib.

BCC tööriistakomplekti kasutamine

Nagu me juba avastasime, kulutab kernel (ja süsteemikutses olev ceph deemon) palju aega generic_make_request(). Proovime mõõta selle funktsiooni kiirust. IN BCC Seal on juba suurepärane utiliit - funclatentsus. Jälgime deemonit selle PID järgi 1-sekundilise intervalliga väljundite vahel ja väljastame tulemuse millisekundites.

Suurest tsefiidi latentsusest kuni eBPF/BCC-ga kerneli paigani
See funktsioon töötab tavaliselt kiiresti. Kõik see edastab päringu seadme draiveri järjekorda.

Bcache on keeruline seade, mis koosneb tegelikult kolmest kettast:

  • tagavaraseade (vahemällu salvestatud ketas), antud juhul on tegemist aeglase HDD-ga;
  • vahemällu salvestav seade (vahemäluketas), siin on see üks NVMe-seadme partitsioon;
  • bcache virtuaalne seade, millega rakendus töötab.

Teame, et päringu edastamine on aeglane, kuid milliste nende seadmete puhul? Sellega tegeleme veidi hiljem.

Nüüd teame, et sündmused põhjustavad tõenäoliselt probleeme. Nende põlvkonna põhjuste leidmine pole nii lihtne. Oletame, et see on mingi perioodiliselt käivitatav tarkvara. Vaatame, milline tarkvara skripti abil süsteemis töötab execsnoop samast BCC utiliit. Käivitame selle ja saadame väljundi faili.

Näiteks nii:

/usr/share/bcc/tools/execsnoop  | tee ./execdump

Me ei näita siin execsnoopi täielikku väljundit, kuid üks meile huvitav rida nägi välja selline:

sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'

Kolmas veerg on protsessi PPID (ema PID). PID 5802-ga protsess osutus meie seiresüsteemi üheks lõimeks. Seiresüsteemi konfiguratsiooni kontrollimisel leiti valed parameetrid. HBA adapteri temperatuuri mõõdeti iga 30 sekundi järel, mis on palju sagedamini kui vaja. Pärast kontrollintervalli muutmist pikemaks avastasime, et päringu töötlemise latentsus sellel hostil ei paistnud enam teiste hostidega võrreldes silma.

Kuid endiselt on ebaselge, miks bcache-seade nii aeglane oli. Valmistasime ette identse konfiguratsiooniga testplatvormi ja proovisime probleemi reprodutseerida, käivitades bcache'is fio, käivitades perioodiliselt udevadm-päästiku, et genereerida usündmusi.

BCC-põhiste tööriistade kirjutamine

Proovime kirjutada lihtsa utiliidi kõige aeglasemate kõnede jälgimiseks ja kuvamiseks generic_make_request(). Oleme huvitatud ka draivi nimest, mille jaoks seda funktsiooni kutsuti.

Plaan on lihtne:

  • Registreeri kprobe edasi generic_make_request():
    • Salvestame ketta nime mällu, millele pääseb juurde funktsiooni argumendi kaudu;
    • Salvestame ajatempli.

  • Registreeri kretprobe naasmiseks generic_make_request():
    • Saame praeguse ajatempli;
    • Otsime salvestatud ajatempli ja võrdleme seda praegusega;
    • Kui tulemus on määratust suurem, leiame salvestatud ketta nime ja kuvame selle terminalis.

Kprobes и kretsondid kasutage katkestuspunkti mehhanismi funktsioonikoodi muutmiseks käigupealt. Saate lugeda dokumentatsioon и hea artikkel sellel teemal. Kui vaatate erinevate utiliitide koode BCC, siis näete, et neil on identne struktuur. Seega jätame selles artiklis vahele skriptiargumentide sõelumise ja liigume edasi BPF-programmi enda juurde.

eBPF-i tekst pythoni skriptis näeb välja selline:

bpf_text = “”” # Here will be the bpf program code “””

Funktsioonide vahel andmete vahetamiseks kasutavad eBPF-i programmid räsi tabelid. Teeme sama. Kasutame võtmena protsessi PID-d ja väärtusena määratleme struktuuri:

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);

Siin registreerime räsitabeli nimega p, võtmetüübiga u64 ja tüübi väärtus struct data_t. Tabel on saadaval meie BPF-programmi kontekstis. Makro BPF_PERF_OUTPUT registreerib teise tabeli nimega sündmused, mida kasutatakse andmeedastus kasutajaruumi.

Mõõtes viivitusi funktsiooni kutsumise ja sealt naasmise vahel või erinevatele funktsioonidele helistamise vahel, tuleb arvestada, et vastuvõetud andmed peavad kuuluma samasse konteksti. Teisisõnu peate meeles pidama funktsioonide võimalikku paralleelset käivitamist. Meil on võimalus mõõta latentsust ühe protsessi kontekstis funktsiooni kutsumise ja teise protsessi kontekstis sellest funktsioonist naasmise vahel, kuid see on tõenäoliselt kasutu. Hea näide oleks siin biolatentsusutiliit, kus räsitabeli võti on seatud kursorile struktuuri taotlus, mis kajastab ühte kettapäringut.

Järgmiseks peame kirjutama koodi, mis käivitub uuritava funktsiooni kutsumisel:

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);
}

Siin asendatakse kutsutud funktsiooni esimene argument teise argumendina generic_make_request(). Pärast seda saame protsessi PID-i, mille kontekstis me töötame, ja praeguse ajatempli nanosekundites. Kirjutame selle kõik üles värskelt valitud struct data_t andmed. Ketta nime saame struktuurist bio, mis helistamisel edasi antakse generic_make_request()ja salvestage see samas struktuuris andmed. Viimane samm on lisada räsitabelisse kirje, mida mainiti varem.

Järgmist funktsiooni kutsutakse tagasi 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);
    }
}

See funktsioon on sarnane eelmisele: selgitame välja protsessi PID ja ajatempli, kuid ei eralda mälu uuele andmestruktuurile. Selle asemel otsime räsitabelist juba olemasolevat struktuuri, kasutades klahvi == praegune PID. Kui struktuur on leitud, siis selgitame välja jooksva protsessi nime ja lisame selle sellele.

Binaarne nihe, mida siin kasutame, on vajalik lõime GID saamiseks. need. Põhiprotsessi PID, mis käivitas lõime, mille kontekstis me töötame. Funktsioon, mida kutsume bpf_get_current_pid_tgid() tagastab nii lõime GID kui ka selle PID ühe 64-bitise väärtusena.

Terminali väljastades ei huvita meid praegu niit, vaid meid huvitab põhiprotsess. Pärast saadud viivituse võrdlemist etteantud lävega läbime oma struktuuri andmed kasutajaruumi tabeli kaudu sündmused, mille järel kustutame kande p.

Pythoni skriptis, mis seda koodi laadib, peame asendama MIN_US ja FACTOR viivituslävede ja ajaühikutega, mida me läbime argumendid:

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"

Nüüd peame BPF-i programmi ette valmistama BPF makro ja registreerige näidised:

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")

Peame ka kindlaks tegema struct data_t meie skriptis, muidu ei saa me midagi lugeda:

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)]

Viimane samm on andmete väljastamine terminali:

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()

Skript ise on saadaval aadressil GItHub. Proovime seda käivitada testplatvormil, kus töötab fio, kirjutab bcache'i ja helista udevadm monitorile:

Suurest tsefiidi latentsusest kuni eBPF/BCC-ga kerneli paigani
Lõpuks ometi! Nüüd näeme, et see, mis nägi välja nagu seiskunud bcache-seade, on tegelikult seiskunud kõne generic_make_request() vahemällu salvestatud ketta jaoks.

Kaevake kernelisse

Mis täpselt päringu edastamise ajal aeglustub? Näeme, et viivitus tekib juba enne päringuarvestuse algust, s.o. konkreetse taotluse arvestamine selle kohta statistika edasiseks väljastamiseks (/proc/diskstats või iostat) ei ole veel alanud. Seda saab hõlpsasti kontrollida, käivitades probleemi taasesitamise ajal iostati või BCC-skripti biolatentsus, mis põhineb päringu arvestuse alguses ja lõpus. Ükski neist utiliitidest ei näita probleeme vahemällu salvestatud ketta päringutega.

Kui vaatame funktsiooni generic_make_request(), siis näeme, et enne päringu arvestuse algust kutsutakse välja veel kaks funktsiooni. Esiteks - generic_make_request_checks(), kontrollib kettaseadete päringu õiguspärasust. Teine - blk_queue_enter(), millel on huvitav väljakutse oota_sündmus_katkestatav():

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));

Selles ootab kernel järjekorra lahtiolekut. Mõõdame viivitust 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    	|                                    	|

Näib, et oleme lahendusele lähedal. Järjekorra külmutamiseks/vabastamiseks kasutatavad funktsioonid on blk_mq_freeze_queue и blk_mq_unfreeze_queue. Neid kasutatakse siis, kui on vaja muuta päringujärjekorra sätteid, mis võivad olla ohtlikud selles järjekorras olevate päringute jaoks. Helistades blk_mq_freeze_queue() funktsioon blk_freeze_queue_start() loendurit suurendatakse q->mq_külmumissügavus. Pärast seda ootab kernel, kuni järjekord tühjendub blk_mq_freeze_queue_wait().

Selle järjekorra tühjendamiseks kuluv aeg võrdub ketta latentsusega, kuna kernel ootab kõigi järjekorda pandud toimingute lõpuleviimist. Kui järjekord on tühi, rakendatakse seadete muudatused. Pärast seda nimetatakse blk_mq_unfreeze_queue(), loenduri vähendamine külmumissügavus.

Nüüd teame piisavalt, et olukorda parandada. Käsk udevadm käivitab blokeerimisseadme seadete rakendamise. Neid sätteid kirjeldatakse udev-i reeglites. Leiame, millised sätted järjekorda külmutavad, proovides neid sysfsi kaudu muuta või kerneli lähtekoodi vaadates. Võime proovida ka BCC utiliiti jälgida, mis väljastab iga terminali kõne jaoks kerneli ja kasutajaruumi pinu jäljed blk_freeze_queue, näiteks:

~# /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]

Udevi reeglid muutuvad üsna harva ja tavaliselt toimub see kontrollitult. Seega näeme, et isegi juba seatud väärtuste rakendamine põhjustab taotluse rakendusest kettale edastamise viivituse. Loomulikult ei ole udev-sündmuste genereerimine, kui ketta konfiguratsioonis muudatusi pole (näiteks seade pole ühendatud/lahti ühendatud), hea tava. Küll aga saame aidata kernelil mitte teha tarbetut tööd ja külmutada taotluste järjekord, kui see pole vajalik. kolm väike pühenduma olukorda parandada.

Järeldus

eBPF on väga paindlik ja võimas tööriist. Artiklis vaatlesime ühte praktilist juhtumit ja demonstreerisime väikest osa sellest, mida saab teha. Kui olete huvitatud BCC utiliitide arendamisest, tasub seda pilku heita ametlik õpetus, mis kirjeldab hästi põhitõdesid.

On ka teisi huvitavaid eBPF-il põhinevaid silumis- ja profiilitööriistu. Üks nendest - bpftrace, mis võimaldab kirjutada võimsaid üherealisi ja väikeseid programme awk-laadses keeles. Teine - ebpf_exporter, võimaldab teil koguda madala taseme ja kõrge eraldusvõimega mõõdikuid otse oma prometheuse serverisse, võimaldades hiljem saada ilusaid visualiseerimisi ja isegi hoiatusi.

Allikas: www.habr.com

Lisa kommentaar