Frá High Ceph Latency til Kernel Patch með eBPF/BCC

Frá High Ceph Latency til Kernel Patch með eBPF/BCC

Linux hefur mikinn fjölda verkfæra til að kemba kjarnann og forritin. Flest þeirra hafa neikvæð áhrif á frammistöðu forrita og er ekki hægt að nota í framleiðslu.

Fyrir nokkrum árum var annað tól hefur verið þróað - eBPF. Það gerir það mögulegt að rekja kjarnann og notendaforrit með litlum tilkostnaði og án þess að þurfa að endurbyggja forrit og hlaða einingar frá þriðja aðila inn í kjarnann.

Það eru nú þegar mörg forritaforrit sem nota eBPF og í þessari grein munum við skoða hvernig á að skrifa þitt eigið prófílforrit byggt á bókasafninu PythonBCC. Greinin er byggð á raunverulegum atburðum. Við munum fara frá vandamáli til að laga til að sýna hvernig hægt er að nota núverandi veitur við sérstakar aðstæður.

Ceph er hægur

Nýr gestgjafi hefur verið bætt við Ceph klasann. Eftir að hafa flutt sum gögnin yfir á það tókum við eftir því að hraði vinnslu skrifbeiðna frá því var mun lægri en á öðrum netþjónum.

Frá High Ceph Latency til Kernel Patch með eBPF/BCC
Ólíkt öðrum kerfum notaði þessi gestgjafi bcache og nýja linux 4.15 kjarnann. Þetta var í fyrsta skipti sem gestgjafi þessarar uppsetningar var notaður hér. Og á þeirri stundu var ljóst að rót vandans gæti fræðilega verið hvað sem er.

Að rannsaka gestgjafann

Við skulum byrja á því að skoða hvað gerist inni í ceph-osd ferlinu. Fyrir þetta munum við nota fullkominn и logasjá (meira um sem þú getur lesið hér):

Frá High Ceph Latency til Kernel Patch með eBPF/BCC
Myndin segir okkur að aðgerðin fdatasync() eyddi miklum tíma í að senda beiðni til aðgerðir generic_make_request(). Þetta þýðir að líklega er orsök vandamálanna einhvers staðar fyrir utan osd púkann sjálfan. Þetta getur verið annað hvort kjarninn eða diskar. Framleiðsla iostat sýndi mikla leynd í vinnslubeiðnum með bcache diskum.

Við athugun á hýsingaraðilanum komumst við að því að systemd-udevd púkinn eyðir miklum tíma CPU - um 20% á nokkrum kjarna. Þetta er undarleg hegðun, svo þú þarft að komast að því hvers vegna. Þar sem Systemd-udevd vinnur með uvents ákváðum við að skoða þá í gegn udevadm fylgjast með. Það kemur í ljós að mikill fjöldi breytingatilvika var myndaður fyrir hvert blokkartæki í kerfinu. Þetta er frekar óvenjulegt, svo við verðum að skoða hvað veldur öllum þessum atburðum.

Með því að nota BCC Toolkit

Eins og við höfum þegar komist að, eyðir kjarninn (og ceph púkinn í kerfiskallinu) miklum tíma í generic_make_request(). Við skulum reyna að mæla hraðann á þessari aðgerð. IN BCC Það er nú þegar dásamlegt tól - virkni. Við munum rekja púkann eftir PID hans með 1 sekúndu bili á milli úttakanna og gefa út niðurstöðuna á millisekúndum.

Frá High Ceph Latency til Kernel Patch með eBPF/BCC
Þessi eiginleiki virkar venjulega fljótt. Allt sem það gerir er að senda beiðnina í biðröð tækjastjóra.

Bcache er flókið tæki sem samanstendur í raun af þremur diskum:

  • bakbúnaður (diskur í skyndiminni), í þessu tilfelli er það hægur HDD;
  • skyndiminnistæki (skyndiminnisdiskur), hér er þetta ein skipting NVMe tækisins;
  • bcache sýndartækið sem forritið keyrir með.

Við vitum að sending beiðni er hæg, en fyrir hvaða af þessum tækjum? Við munum takast á við þetta aðeins síðar.

Við vitum núna að atburðir eru líklegir til að valda vandamálum. Það er ekki svo auðvelt að finna hvað nákvæmlega veldur kynslóð þeirra. Gerum ráð fyrir að þetta sé einhvers konar hugbúnaður sem er opnaður reglulega. Við skulum sjá hvers konar hugbúnað keyrir á kerfinu með handriti execsnoop frá sama BCC tólasett. Við skulum keyra það og senda úttakið í skrá.

Til dæmis svona:

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

Við munum ekki sýna heildarúttak execsnoop hér, en ein lína sem vekur áhuga okkar leit svona út:

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

Þriðji dálkurinn er PPID (foreldri PID) ferlisins. Ferlið með PID 5802 reyndist vera einn af þráðum eftirlitskerfisins okkar. Við skoðun á uppsetningu eftirlitskerfisins fundust rangar breytur. Hitastig HBA millistykkisins var tekið á 30 sekúndna fresti, sem er mun oftar en nauðsynlegt er. Eftir að hafa breytt eftirlitsbilinu í lengra komumst við að því að biðtíminn fyrir vinnslu beiðna á þessum hýsil var ekki lengur áberandi í samanburði við aðra gestgjafa.

En það er enn óljóst hvers vegna bcache tækið var svona hægt. Við útbjuggum prófunarvettvang með sömu uppsetningu og reyndum að endurskapa vandamálið með því að keyra fio á bcache, keyra reglulega udevadm trigger til að búa til uevents.

Að skrifa BCC-undirstaða verkfæri

Við skulum reyna að skrifa einfalt tól til að rekja og sýna hægustu símtölin generic_make_request(). Við höfum líka áhuga á nafni drifsins sem þessi aðgerð var kölluð fyrir.

Áætlunin er einföld:

  • Skráðu þig kprobe á generic_make_request():
    • Við vistum disknafnið í minni, aðgengilegt í gegnum fallarrilefnið;
    • Við vistum tímastimpilinn.

  • Skráðu þig kretprobe til skila frá generic_make_request():
    • Við fáum núverandi tímastimpil;
    • Við leitum að vistuðum tímastimplinum og berum það saman við núverandi;
    • Ef niðurstaðan er meiri en tilgreind, finnum við vistaða disknafnið og birtum það á flugstöðinni.

Kprobes и kretprobes notaðu brotpunktabúnað til að breyta aðgerðakóða á flugi. Þú getur lesið skjöl и gott grein um þetta efni. Ef þú skoðar kóða ýmissa tóla í BCC, þá geturðu séð að þeir hafa sömu uppbyggingu. Svo í þessari grein munum við sleppa því að flokka forskriftarrök og halda áfram í BPF forritið sjálft.

eBPF textinn inni í python handritinu lítur svona út:

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

Til að skiptast á gögnum á milli aðgerða nota eBPF forrit kjötkássa töflur. Við munum gera það sama. Við munum nota ferli PID sem lykilinn og skilgreina uppbyggingu sem gildi:

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 skráum við kjötkássatöflu sem heitir p, með lyklagerð u64 og tegundargildi struct data_t. Taflan verður fáanleg í tengslum við BPF áætlunina okkar. BPF_PERF_OUTPUT fjölvi skráir aðra töflu sem heitir Viðburðir, sem er notað fyrir gagnaflutningur inn í notendarými.

Þegar mælt er á töfum á milli þess að hringja í aðgerð og til baka úr henni, eða á milli símtala í mismunandi aðgerðir, þarf að taka tillit til þess að móttekin gögn verða að tilheyra sama samhengi. Með öðrum orðum, þú þarft að muna um hugsanlega samhliða ræsingu aðgerða. Við höfum getu til að mæla leynd á milli þess að kalla fall í samhengi við eitt ferli og til baka frá því falli í samhengi við annað ferli, en þetta er líklega gagnslaust. Gott dæmi hér væri gagnsemi líftíma, þar sem kjötkássatöflulykillinn er stilltur á bendil á struct beiðni, sem endurspeglar eina diskabeiðni.

Næst þurfum við að skrifa kóðann sem mun keyra þegar aðgerðin sem er í rannsókn er kölluð:

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 verður fyrsta röksemdin í kölluðu falli skipt út fyrir önnur rök generic_make_request(). Eftir þetta fáum við PID ferlisins í því samhengi sem við erum að vinna og núverandi tímastimpil á nanósekúndum. Við skrifum þetta allt niður í nývöldum struct data_t gögn. Við fáum nafn disksins frá uppbyggingunni líf, sem er samþykkt þegar hringt er generic_make_request(), og vistaðu það í sömu uppbyggingu gögn. Síðasta skrefið er að bæta við færslu í kjötkássatöfluna sem áður var nefnd.

Eftirfarandi aðgerð verður kölluð til baka frá 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);
    }
}

Þessi aðgerð er svipuð þeirri fyrri: við finnum út PID ferlisins og tímastimpilinn, en úthlutum ekki minni fyrir nýju gagnaskipulagið. Í staðinn leitum við í kjötkássatöflunni að uppbyggingu sem þegar er til með því að nota lykilinn == núverandi PID. Ef uppbyggingin finnst finnum við nafnið á ferlinu sem er í gangi og bætum því við það.

Tvíundarvaktin sem við notum hér er nauðsynleg til að fá þráðinn GID. þeim. PID af aðalferlinu sem byrjaði þráðinn í því samhengi sem við erum að vinna. Fallið sem við köllum bpf_get_current_pid_tgid() skilar bæði GID þráðsins og PID hans í einu 64 bita gildi.

Þegar við sendum út í flugstöðina höfum við ekki áhuga á þræðinum eins og er, en við höfum áhuga á aðalferlinu. Eftir að hafa borið saman seinkunina sem myndast við tiltekinn þröskuld, förum við yfir uppbyggingu okkar gögn inn í notendarými í gegnum töflu Viðburðir, eftir það eyðum við færslunni frá p.

Í python skriftunni sem mun hlaða þessum kóða, þurfum við að skipta um MIN_US og FACTOR fyrir seinkun þröskulda og tímaeiningar, sem við munum fara í gegnum rökin:

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ú þurfum við að undirbúa BPF forritið í gegnum BPF makró og skrá sýni:

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ð verðum líka að ákveða struct data_t í handritinu okkar, annars getum við ekki lesið neitt:

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

Síðasta skrefið er að gefa út gögn í flugstöðina:

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

Handritið sjálft er fáanlegt á GItHub. Við skulum reyna að keyra það á prófunarvettvangi þar sem fio er í gangi, skrifa í bcache og hringja í udevadm monitor:

Frá High Ceph Latency til Kernel Patch með eBPF/BCC
Loksins! Nú sjáum við að það sem leit út eins og bcache tæki sem stöðvast er í raun stöðvunarsímtal generic_make_request() fyrir disk í skyndiminni.

Grafið í kjarnann

Hvað nákvæmlega er að hægja á meðan á sendingu beiðni stendur? Við sjáum að seinkunin á sér stað jafnvel áður en byrjað er á beiðnibókhaldi, þ.e. bókhald á tiltekinni beiðni um frekari framleiðsla tölfræði um hana (/proc/diskstats eða iostat) er ekki enn hafin. Þetta er auðvelt að sannreyna með því að keyra iostat á meðan þú endurskapar vandamálið, eða BCC skriftu lífstíðni, sem byggir á upphaf og lok beiðnibókhalds. Ekkert af þessum tólum mun sýna vandamál fyrir beiðnir á skyndiminni diskinn.

Ef við skoðum fallið generic_make_request(), þá munum við sjá að áður en beiðnin byrjar bókhald, eru tvær aðgerðir til viðbótar kallaðar. Fyrst - generic_make_request_checks(), framkvæmir athuganir á lögmæti beiðninnar varðandi diskstillingar. Annað - blk_queue_enter(), sem hefur áhugaverða áskorun wait_event_interruptible():

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

Í henni bíður kjarninn eftir að biðröðin losni. Mælum seinkunina 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    	|                                    	|

Það lítur út fyrir að við séum nálægt lausn. Aðgerðirnar sem notaðar eru til að frysta/affrysta biðröð eru blk_mq_freeze_queue и blk_mq_unfreeze_queue. Þær eru notaðar þegar nauðsynlegt er að breyta stillingum biðröðarinnar, sem eru hugsanlega hættulegar fyrir beiðnir í þessari biðröð. Þegar hringt er blk_mq_freeze_queue() virka blk_freeze_queue_start() teljarinn er hækkaður q->mq_frysta_dýpt. Eftir þetta bíður kjarninn eftir að biðröðin tæmist blk_mq_freeze_queue_wait().

Tíminn sem það tekur að hreinsa þessa biðröð jafngildir biðtíma disks þar sem kjarninn bíður eftir að allar aðgerðir í biðröð ljúki. Þegar röðin er tóm eru stillingarbreytingarnar beittar. Eftir það er það kallað blk_mq_unfreeze_queue(), lækkar teljarann freeze_depth.

Nú vitum við nóg til að leiðrétta ástandið. Udevadm kveikja skipunin veldur því að stillingum fyrir blokkarbúnaðinn er beitt. Þessum stillingum er lýst í udev reglunum. Við getum fundið hvaða stillingar eru að frysta biðröðina með því að reyna að breyta þeim í gegnum sysfs eða með því að skoða frumkóðann í kjarnanum. Við getum líka prófað BCC tólið rekja, sem mun gefa út kjarna- og notendarýmisstaflaspor fyrir hvert símtal í flugstöðina blk_freeze_queue, til dæmis:

~# /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 reglur breytast frekar sjaldan og venjulega gerist þetta á stjórnaðan hátt. Þannig að við sjáum að jafnvel að beita þegar stilltum gildum veldur aukinni töf á að flytja beiðnina frá forritinu yfir á diskinn. Auðvitað er ekki góð æfing að búa til udev atburði þegar engar breytingar eru á diskstillingunni (td tækið er ekki tengt/aftengdur). Hins vegar getum við hjálpað kjarnanum að vinna ekki óþarfa vinnu og fryst beiðniröðina ef það er ekki nauðsynlegt. Þrír litlu börnin skuldbinda sig leiðrétta ástandið.

Niðurstaða

eBPF er mjög sveigjanlegt og öflugt tæki. Í greininni skoðuðum við eitt hagnýtt tilvik og sýndum lítinn hluta af því sem hægt er að gera. Ef þú hefur áhuga á að þróa BCC tól, þá er það þess virði að kíkja á opinber kennsluefni, sem lýsir grunnatriðum vel.

Það eru önnur áhugaverð kembiforrit og prófílunarverkfæri byggð á eBPF. Einn af þeim - bpftrace, sem gerir þér kleift að skrifa kraftmikla einlínu og smáforrit á hinu asnalega tungumáli. Annað - ebpf_exporter, gerir þér kleift að safna lágu stigi, háupplausnarmælingum beint inn á Prometheus netþjóninn þinn, með möguleika á að fá fallegar sjónmyndir síðar og jafnvel viðvaranir.

Heimild: www.habr.com

Bæta við athugasemd