Në Linux ka një numër të madh mjetesh për debugsimin e kernel-it dhe aplikacioneve. Shumica e tyre ndikojnë negativisht në performancën e aplikacioneve dhe nuk mund të përdoren në prodhim.
Para disa vjetësh u zhvillua një tjetër mjet Tani ekzistojnë shumë utilitare praktike që përdorin eBPF, dhe në këtë artikull do të shqyrtojmë se si të shkruajmë utilitarin tonë për profilimin bazuar në bibliotekën
PythonBCC . Artikulli bazohet në ngjarje të vërteta. Ne do të kalojmë nga shfaqja e problemit deri te zgjidhja e tij, për të treguar se si mund të përdoren utilitarët ekzistues në situata specifike.
Ceph është ngadalë
Në klustërin Ceph u shtua një host i ri. Pas migrimit të një pjese të të dhënave te ai, vumë re se shpejtësia e përpunimit të kërkesave për shkarkim ishte shumë më e ulët se në serverat e tjerë.
Ndryshe nga platformat e tjera, në këtë host u përdor bcache dhe një bërthamë e re linux 4.15. Ky host me këtë konfigurim ishte përdorur këtu për herë të parë. Dhe në atë moment ishte e qartë se shkaku i problemit mund të ishte teorikisht çdo gjë.
KĂ«rkimi i Hostit
Le të fillojmë me atë që ndodh brenda procesit ceph-osd. Për këtë do të përdorim dhe (mund të lexoni më shumë rreth të cilave ):
Imazhi na tregon se funksioni fdatasync() ka kaluar shumë kohë gjatë dërgimit të një kërkese në funksionin generic_make_request(). Kjo do të thotë se, shumë shpejt, problemi ndodhet diku jashtë vetë demonit osd. Kjo mund të jetë ose bërthama, ose diskët. Shfaqja e iostat tregonte vonesa të larta në përpunimin e kërkesave nga diskët bcache.
GjatĂ« kontrollit tĂ« hostit, ne zbuluam se demoni systemd-udevd konsumonte njĂ« sasi tĂ« madhe kohe CPU â rreth 20% nĂ« disa bĂ«rthama. Ky Ă«shtĂ« njĂ« sjellje e çuditshme, kĂ«shtu qĂ« duhet tĂ« kuptojmĂ« shkakun e saj. Duke qenĂ« se Systemd-udevd punon me ueventĂ«t, ne vendosĂ«m tĂ« shikojmĂ« pĂ«r to nĂ«pĂ«rmjet udevadm monitor. Doli se po gjeneroheshin shumĂ« ngjarje ndryshimi pĂ«r çdo pajisje blloku nĂ« sistem. Kjo Ă«shtĂ« mjaft e pazakontĂ«, prandaj do tĂ« jetĂ« e nevojshme tĂ« shikojmĂ« se çfarĂ« po gjeneron kĂ«to ngjarje.
PĂ«rdorimi i BCC Toolkit
Siç e konstatuam, bĂ«rthama (dhe demoni ceph nĂ« thirrjen e sistemit) kalon shumĂ« kohĂ« nĂ« generic_make_request(). Le tĂ« pĂ«rpiqemi tĂ« matim shpejtĂ«sinĂ« e punĂ«s sĂ« kĂ«tij funksioni. NĂ« ka njĂ« utilitar tĂ« shkĂ«lqyer â funclatency. Ne do tĂ« vijojmĂ« demonin sipas PID tĂ« tij me njĂ« interval midis info-sh pĂ«r çdo 1 sekondĂ« dhe do tĂ« nxjerrim rezultatin nĂ« milisekonda.
Zakonisht ky funksion punon shpejt. E gjithë ajo që bën është të dërgojë një kërkesë në radhën e drejtuesit të pajisjes.
Bcache â Ă«shtĂ« njĂ« pajisje e komplikuar qĂ« nĂ« tĂ« vĂ«rtetĂ« pĂ«rbĂ«het nga tre disqe:
- disqet mbështetëse (disku që ndihmon), në këtë rast është një HDD i ngadalshëm;
- disku që ndihmon (disku i caching), këtu është një ndarje NVMe e pajisjes;
- pajisja virtuale bcache, me të cilën punon aplikacioni.
E dimë që dërgimi i kërkesës është ngadalësuar, por për cilin nga këto disqe? Do ta zbulojmë këtë më vonë.
Tani e dimë se ueventët, ndoshta, po shkaktojnë probleme. Të gjejmë se çfarë pikërisht shkakton gjenerimin e tyre, nuk është kaq e thjeshtë. Le të supozojmë se është ndonjë softuer që ekzekutohet periodikisht. Le të shohim se çfarë software po ekzekutohet në sistem, me ndihmën e skenarit execsnoop nga të njëjtën . Le të eci dhe të drejtojmë daljen në një skedar.
PĂ«r shembull, ashtu:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nuk do të japim këtu daljen e plotë të execsnoop, por një rresht që na intereson dukej kështu:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Kolona e tretë është PPID (PID i prindit) të procesit. Procesi me PID 5802 rezultoi të ishte një nga fijet e sistemit tonë të monitorimit. Gjatë kontrollit të konfigurimit të sistemit të monitorimit u gjetën parametra të caktuar gabimisht. Temperatura e adaptorit HBA u mat një herë në 30 sekonda, që ishte shumë më shpesh se nevojitej. Pas ndryshimit të intervalit të kontrollit në një më të gjatë, vërejti se vonesa në të përpunuarit e kërkesave në këtë host kishte ndaluar të dalë në pah në krahasim me hostet e tjerë.
Por akoma nuk është e qartë pse pajisja bcache ka qenë kaq e ngadaltë. Ne përgatitëm një platformë testuese me konfigurim identik dhe përpiqemi të riprodhojmë problemin duke ekzekutuar fio në bcache, duke ekzekutuar periodikisht udevadm trigger për të gjeneruar uevents.
Shkrimi i Veglave të BCC
Le të përpiqemi të shkruajmë një utilitar të thjeshtë për të gjurmë dhe shfaqur thirrjet më të ngadalta generic_make_request(). Ne gjithashtu na intereson emri i diskut për të cilin u thirr ky funksion.
Plani është i thjeshtë:
- gitlab-runner. kprobe në generic_make_request():
- Ruajmë në memorie emrin e diskut, i cili është i disponueshëm përmes argumentit të funksionit;
- Ruajmë shenjën e kohës.
- gitlab-runner. kretprobe në kthim nga generic_make_request():
- Marrim shenjën aktuale të kohës;
- Kërkojmë shenjën e ruajtur të kohës dhe e krahasojmë me të tanishmen;
- Nëse rezultati është më i madh se i caktuari, atëherë gjejmë emrin e ruajtur të diskut dhe e shfaqim në terminal.
Kprobes dhe kretprobes përdorin mekanizmat e pikave të bllokimit për të modifikuar kodin e funksioneve në fluks. Mund të lexoni dhe artikul të mirë mbi këtë temë. Nëse shikoni kodin e disa utiliteteve në , mund të vëreni se ato kanë një strukturë identike. Kështu që në këtë artikull do të kalojmë përpara duke lënë mënjanë analizimin e argumenteve të skriptit dhe do të kalojmë direkt në programin BPF.
Teksti eBPF brenda skriptit python duket si më poshtë:
bpf_text = """ # Këtu do të jetë kodi i programit bpf """
Për shkëmbimin e të dhënave midis funksioneve, programet e eBPF përdorin . Kështu do të veprojmë edhe ne. Si çelës do të përdorim PID-në e procesit dhe si vlerë do të përcaktojmë strukturën:
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);
Këtu regjistrojmë një tabelë hash, e cila quhet p, me çelës të tipit u64 dhe vlerë të tipit struct data_t. Tabela do të jetë e aksesueshme në kontekstin e programit tonë BPF. Makrosi BPF_PERF_OUTPUT regjistron një tabelë tjetër, të quajtur events., e cila përdoret për në hapësirën e përdoruesit.
Kur matim vonesat midis thirrjes së funksionit dhe kthimit prej tij, ose midis thirrjeve të funksioneve të ndryshme, duhet të kemi parasysh se të dhënat e marra duhet të përkasin të njëjtit kontekst. me fjalë të tjera, duhet të kujdesemi për mundësinë e ekzekutimit paralel të funksioneve. Ne kemi mundësinë të masim vonesën midis thirrjes së funksionit në kontekstin e një procesi dhe kthimit nga ky funksion në kontekstin e një procesi tjetër, por kjo, me siguri, do të ishte e padobishme. Një shembull i mirë këtu mund të jetë , ku si çelësi i tabelës hash caktohet një tregues në struct request, që reflekton një kërkesë të vetme në disk.
Më pas na nevojitet të shkruajmë kodin, i cili do të ekzekutohet kur thirret funksioni i hulumtuar:
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);
}
Këtu si argument të dytë do të vendoset argumenti i parë i thirrjes së funksionit . Pas kësaj ne marrim PID-në e procesit, në kontekstin e të cilit punojmë, dhe vulën aktuale të kohës në nanosekonda. E gjithë kjo e shkruajmë në një struct data_t data. Emrin e diskut e marrim nga struktura bio, që kalojnë gjatë thirrjes generic_make_request(), dhe e ruajmë atë në të njëjtën strukturë data. Hapi përfundimtar është të shtojmë një shënim në tabelën hash, të cilën e përmendëm më parë.
Funksioni i ardhshëm do të thirret në kthimin nga 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);
}
}
Ky funksion është i ngjashëm me të kaluarin: ne mësojmë PID-në e procesit dhe vulën e kohës, por nuk alokojmë memorie për një strukturë të re data. Në vend të kësaj, ne kërkojmë në tabelën hash strukturën ekzistuese me çelës = PID-në aktuale. Nëse strukura gjendet, ne mësojmë emrin e procesit të ekzekutuar dhe e shtojmë atë brenda.
Lëvizja binare që ne po përdorim këtu është e nevojshme për të marrë GID-in e thread-it. Pra, PID-i i procesit kryesor që ka nisur thread-in, në kontekstin e të cilit ne po punojmë. Funksioni ynë i thirrur kthen si GID të threadit, ashtu edhe PID-in e tij në një vlerë 64-bit.
Kur e drejtojmë në terminal aktualisht nuk na intereson threadi, por procesi kryesor. Pas krahasimit të vonesës së marrë me pragun e caktuar, ne e kalojmë strukturën tonë data në hapësirën e përdoruesit përmes tabelës events., pas së cilës ne e fshijmë shënimin nga p.
Në skriptin python, i cili do të ngarkohet ky kod, ne duhet të zëvendësojmë MIN_US dhe FACTOR me pragjet e vonesës dhe njësitë e kohës që ne do të kalojmë përmes argumenteve:
bpf_text = bpf_text.replace('MIN_US',str(min_usec))
if args.milliseconds:
bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;')
label = "msec"
elif:
bpf_text = bpf_text.replace('FACTOR','')
label = "usec"
Tani na nevojitet të përgatitim programin BPF përmes dhe të regjistrojmë provat:
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")
Gjithashtu do të duhet të përcaktojmë struct data_t në skriptin tonë, përndryshe nuk do të jetë e mundur të lexojmë asgjë:
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)]
Hapi i fundit është të printoni të dhënat në 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()
Skripti është në dispozicion në . Le të përpiqemi ta ekzekutojmë në një platformë provuese, ku është aktivizuar fio që shkruan në bcache, dhe të therrasim udevadm monitor:
Në fund! Tani e shohim se ajo që dukej si një ndalesë e bcache-it, në të vërtetë është një ndalesë e thirrjes generic_make_request() për diskun e ruajtur.
Hulumtoni thellë në Kernel
ĂfarĂ« saktĂ«sisht po ngadalĂ«son gjatĂ« kalimit tĂ« kĂ«rkesĂ«s? Ne shohim se vonesa ndodh edhe para fillimit tĂ« logjikĂ«s sĂ« kĂ«rkesĂ«s, dmth. regjistrimi i kĂ«rkesĂ«s specifike pĂ«r dalje statistike pĂ«r tĂ« (/proc/diskstats ose iostat) ende nuk ka filluar. Kjo mund tĂ« verifikohet lehtĂ«sisht duke ekzekutuar iostat gjatĂ« riprodhimit tĂ« problemit, ose , i cili bazohet nĂ« fillimin dhe pĂ«rfundimin e logjikĂ«s sĂ« kĂ«rkesave. AsnjĂ«ra nga kĂ«to mjete nuk do tĂ« tregojĂ« probleme pĂ«r kĂ«rkesat pĂ«r diskun e ruajtur.
Nëse shikojmë funksionin generic_make_request(), do të shohim se para fillimit të logjikës së kërkesës thirren edhe dy funksione të tjera. I pari është generic_make_request_checks(), i cili kryen kontrollet e legjitimitetit të kërkesës në lidhje me konfigurimet e diskut. I dyti është , ku ka një thirrje interesante :
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));
Në të, kernel-i pret për të zbuluar qendrën. Le të matim vonesën blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Duke gjurmuar 1 funksione për "blk_queue_enter"... Shtypni Ctrl-C për të përfunduar.
msecs : count distribucioni
0 -> 1 : 341 |****************************************|
msecs : count distribucioni
0 -> 1 : 316 |****************************************|
msecs : count distribucioni
0 -> 1 : 255 |****************************************|
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 1 | |
Duket se jemi afër zgjidhjes. Funksionet e përdorura për "ngrirjen/shkrirjen" e qendrës janë dhe . Ato përdoren kur është e nevojshme të modifikoni konfigurimet e qendrës së kërkesave, potencialisht të rrezikshme për kërkesat që ndodhen në këtë radhë. Kur thirret blk_mq_freeze_queue() nga funksioni numri i q->mq_freeze_depth. Pasi, kernel-i pret deri në zbrazjen e qendrës në .
Koha e pritjes për të zbrazur këtë qendër barazvlenë me vonesën e diskut, pasi kernel-i pret për përfundimin e të gjithë operacioneve të radhitura. Sapo qendra të zbrazet, aplikohen ndryshimet e konfigurimeve. Pas kësaj, thirret , që dekrementon numrin freeze_depth.
Tani e dimĂ« mjaftueshĂ«m pĂ«r tĂ« rregulluar situatĂ«n. Komanda udevadm trigger rezulton nĂ« aplikimin e konfigurimeve pĂ«r pajisjen bllokuese. KĂ«to konfigurime pĂ«rshkruhen nĂ« rregullat e udev. Mund tĂ« gjejmĂ« se cilat konfigurime "ngrin" qendrĂ«n, duke provuar tâi ndryshojmĂ« ato pĂ«rmes sysfs ose duke parĂ« kodin burimor tĂ« kernel-it. Gjithashtu mund tĂ« provojmĂ« mjetin BCC , i cili do tĂ« nxjerrĂ« nĂ« terminal gjurmĂ«t e stack-Ă«s sĂ« kernel-it dhe hapĂ«sirĂ«s sĂ« pĂ«rdoruesit pĂ«r çdo thirrje blk_freeze_queue, pĂ«r shembull:
~# /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]
Rregullat e udev ndryshojnë mjaft rrallë dhe zakonisht ndodhin në mënyrë të kontrolluar. Kështu që shohim se madje edhe aplikimi i vlerave tashmë të caktuara shkakton një shpërthim të vonesës së kalimit të kërkesës nga aplikacioni në disk. Sigurisht, gjenerimi i ngjarjeve të udev kur nuk ka ndryshime në konfigurimin e disqeve (p.sh., pajisja nuk lidhet/çlirohet) nuk është një praktikë e mirë. Megjithatë, mund të ndihmojmë kernelin të mos bëjë punë të panevojshme dhe të mos "ngrihet" radhë kërkesash, nëse nuk ka një nevojë të tillë. zgjidhin situatën.
PĂ«rfundimi
eBPF është një instrument shumë fleksibël dhe i fuqishëm. Në këtë artikull shqyrtuam një rast praktik dhe demonstruam një pjesë të vogël të asaj që është e mundur të bëhet. Nëse jeni të interesuar në zhvillimin e mjeteve BCC, ia vlen të shikoni , i cili përshkruan mirë bazat e funksionimit.
Ka edhe mjete të tjera interesante për debugging dhe profilizim të bazuara në eBPF. Një prej tyre është , i cili lejon të shkruani njëlinjësh të fuqishëm dhe programe të vogla në një gjuhë të ngjashme me awk. Një tjetër është , lejonë mbledhjen e metrikave të nivelit të ulët me një saktësi të lartë direkt në serverin tuaj prometheus, me mundësinë për të marrë një vizualizim të bukur dhe madje alarme më vonë.
Burimi: habr.com
