Linux har et stort antal værktøjer til fejlretning af kernen og applikationer. De fleste af dem har en negativ indvirkning på applikationens ydeevne og kan ikke bruges i produktionen.
For et par år siden var der - eBPF. Det gør det muligt at spore kernen og brugerapplikationer med lav overhead og uden behov for at genopbygge programmer og indlæse tredjepartsmoduler i kernen.
Der er allerede mange applikationsværktøjer, der bruger eBPF, og i denne artikel vil vi se på, hvordan du skriver dit eget profileringsværktøj baseret på biblioteket . Artiklen er baseret på virkelige begivenheder. Vi går fra problem til løsning for at vise, hvordan eksisterende hjælpeprogrammer kan bruges i specifikke situationer.
Ceph er langsom
En ny vært er blevet tilføjet til Ceph-klyngen. Efter at have migreret nogle af dataene til det, bemærkede vi, at hastigheden for behandling af skriveanmodninger af den var meget lavere end på andre servere.
I modsætning til andre platforme brugte denne vært bcache og den nye linux 4.15-kerne. Dette var første gang en vært for denne konfiguration blev brugt her. Og i det øjeblik stod det klart, at roden til problemet teoretisk set kunne være hvad som helst.
Undersøgelse af værten
Lad os starte med at se på, hvad der sker inde i ceph-osd-processen. Til dette vil vi bruge и (mere om, som du kan læse ):
Billedet fortæller os, at funktionen fdatasync() brugt meget tid på at sende en forespørgsel til funktioner generic_make_request(). Dette betyder, at årsagen til problemerne højst sandsynligt er et sted uden for osd-dæmonen selv. Dette kan enten være kernen eller diske. Iostat-outputtet viste en høj latenstid i behandlingen af anmodninger fra bcache-diske.
Da vi tjekkede værten, fandt vi ud af, at systemd-udevd-dæmonen bruger en stor mængde CPU-tid - omkring 20% på flere kerner. Det er mærkelig adfærd, så du skal finde ud af hvorfor. Da Systemd-udevd arbejder med uevents, besluttede vi at se dem igennem udevadm monitor. Det viser sig, at der blev genereret et stort antal ændringshændelser for hver blokenhed i systemet. Dette er ret usædvanligt, så vi bliver nødt til at se på, hvad der genererer alle disse begivenheder.
Brug af BCC Toolkit
Som vi allerede har fundet ud af, bruger kernen (og ceph-dæmonen i systemkaldet) meget tid i generic_make_request(). Lad os prøve at måle hastigheden af denne funktion. I Der er allerede et vidunderligt værktøj - funktionalitet. Vi vil spore dæmonen ved dens PID med et 1 sekunds interval mellem output og udlæse resultatet i millisekunder.
Denne funktion fungerer normalt hurtigt. Alt det gør er at sende anmodningen til enhedsdriverkøen.
Bcache er en kompleks enhed, der faktisk består af tre diske:
- backing-enhed (cachelagret disk), i dette tilfælde er det en langsom HDD;
- cache-enhed (cache-disk), her er dette en partition af NVMe-enheden;
- den virtuelle bcache-enhed, som applikationen kører med.
Vi ved, at anmodningstransmission er langsom, men for hvilke af disse enheder? Vi behandler dette lidt senere.
Vi ved nu, at uhændelser sandsynligvis vil forårsage problemer. Det er ikke så let at finde ud af, hvad der præcist forårsager deres generation. Lad os antage, at dette er en form for software, der lanceres med jævne mellemrum. Lad os se, hvilken slags software der kører på systemet ved hjælp af et script execsnoop fra samme . Lad os køre det og sende output til en fil.
For eksempel sådan her:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Vi vil ikke vise det fulde output af execsnoop her, men en linje af interesse for os så sådan ud:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Den tredje kolonne er PPID (overordnet PID) for processen. Processen med PID 5802 viste sig at være en af trådene i vores overvågningssystem. Ved kontrol af konfigurationen af overvågningssystemet blev der fundet fejlagtige parametre. Temperaturen på HBA-adapteren blev målt hvert 30. sekund, hvilket er meget oftere end nødvendigt. Efter at have ændret kontrolintervallet til et længere, fandt vi ud af, at anmodningsbehandlingsforsinkelsen på denne vært ikke længere skilte sig ud sammenlignet med andre værter.
Men det er stadig uklart, hvorfor bcache-enheden var så langsom. Vi forberedte en testplatform med en identisk konfiguration og forsøgte at reproducere problemet ved at køre fio på bcache, med jævne mellemrum at køre udevadm trigger for at generere uevents.
Skrivning af BCC-baserede værktøjer
Lad os prøve at skrive et simpelt værktøj til at spore og vise de langsomste opkald generic_make_request(). Vi er også interesserede i navnet på det drev, som denne funktion blev kaldt.
Planen er enkel:
- Tilmeld kprobe på generic_make_request():
- Vi gemmer disknavnet i hukommelsen, tilgængeligt via funktionsargumentet;
- Vi gemmer tidsstemplet.
- Tilmeld kretprobe til retur fra generic_make_request():
- Vi får det aktuelle tidsstempel;
- Vi leder efter det gemte tidsstempel og sammenligner det med det nuværende;
- Hvis resultatet er større end det angivne, finder vi det gemte disknavn og viser det på terminalen.
Kprobes и kretprobes bruge en breakpoint-mekanisme til at ændre funktionskode på farten. Du kan læse и artikel om dette emne. Hvis du ser på koden for forskellige hjælpeprogrammer i , så kan du se, at de har en identisk struktur. Så i denne artikel vil vi springe over at analysere script-argumenter og gå videre til selve BPF-programmet.
eBPF-teksten inde i python-scriptet ser sådan ud:
bpf_text = “”” # Here will be the bpf program code “””
For at udveksle data mellem funktioner, bruger eBPF-programmer . Vi vil gøre det samme. Vi vil bruge processen PID som nøglen og definere strukturen som værdien:
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);
Her registrerer vi en hash-tabel kaldet p, med nøgletype u64 og en typeværdi struct data_t. Tabellen vil være tilgængelig i forbindelse med vores BPF-program. BPF_PERF_OUTPUT-makroen registrerer en anden tabel kaldet begivenheder, som bruges til ind i brugerrummet.
Ved måling af forsinkelser mellem opkald af en funktion og retur fra den, eller mellem opkald til forskellige funktioner, skal du tage højde for, at de modtagne data skal tilhøre samme kontekst. Du skal med andre ord huske på den mulige parallelle lancering af funktioner. Vi har evnen til at måle latensen mellem at kalde en funktion i sammenhæng med én proces og at vende tilbage fra den funktion i sammenhæng med en anden proces, men dette er sandsynligvis ubrugeligt. Et godt eksempel her ville være , hvor hash-tabelnøglen er sat til en pegepind til struct anmodning, som afspejler én diskanmodning.
Dernæst skal vi skrive koden, der kører, når funktionen under undersøgelse kaldes:
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);
}
Her vil det første argument af den kaldte funktion blive erstattet som det andet argument . Herefter får vi PID for den proces, som vi arbejder i, og det aktuelle tidsstempel i nanosekunder. Vi skriver det hele ned i en frisk udvalgt struct data_t data. Vi får disknavnet fra strukturen bio, som er bestået ved opkald generic_make_request(), og gem det i samme struktur data. Det sidste trin er at tilføje en post til hash-tabellen, der blev nævnt tidligere.
Følgende funktion vil blive kaldt ved retur fra 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);
}
}
Denne funktion ligner den forrige: vi finder ud af processens PID og tidsstemplet, men allokerer ikke hukommelse til den nye datastruktur. I stedet søger vi i hash-tabellen efter en allerede eksisterende struktur ved hjælp af nøglen == aktuel PID. Hvis strukturen er fundet, finder vi navnet på den kørende proces og tilføjer den til den.
Det binære skift, vi bruger her, er nødvendigt for at få tråden GID. de der. PID af hovedprocessen, der startede tråden i den sammenhæng, vi arbejder med. Funktionen kalder vi returnerer både trådens GID og dens PID i en enkelt 64-bit værdi.
Når vi udsender til terminalen, er vi i øjeblikket ikke interesserede i tråden, men vi er interesserede i hovedprocessen. Efter at have sammenlignet den resulterende forsinkelse med en given tærskel, passerer vi vores struktur data ind i brugerrummet via tabel begivenheder, hvorefter vi sletter posten fra p.
I python-scriptet, der vil indlæse denne kode, skal vi erstatte MIN_US og FACTOR med forsinkelsestærsklerne og tidsenhederne, som vi sender gennem argumenterne:
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"
Nu skal vi forberede BPF-programmet via og registerprøver:
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 bliver også nødt til at bestemme struct data_t i vores manuskript, ellers kan vi ikke læse noget:
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 sidste trin er at udlæse data til 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)
# format output
start = 0
while 1:
try:
b.perf_buffer_poll()
except KeyboardInterrupt:
exit()
Selve scriptet er tilgængeligt på . Lad os prøve at køre det på en testplatform, hvor fio kører, skriver til bcache og kalder udevadm monitor:
Endelig! Nu ser vi, at det, der lignede en stalling bcache-enhed, faktisk er et stalling call generic_make_request() for en cachelagret disk.
Grav ned i kernen
Hvad er det præcist, der går langsommere under anmodningstransmission? Vi ser, at forsinkelsen sker allerede før start af anmodningsregnskab, dvs. regnskabsføring af en specifik anmodning om yderligere output af statistik på den (/proc/diskstats eller iostat) er endnu ikke begyndt. Dette kan nemt verificeres ved at køre iostat, mens problemet reproduceres, eller , som er baseret på start og afslutning af anmodningsregnskab. Ingen af disse hjælpeprogrammer vil vise problemer for anmodninger til den cachelagrede disk.
Hvis vi ser på funktionen generic_make_request(), så vil vi se, at før anmodningsregnskabet begynder, kaldes yderligere to funktioner. Først - generic_make_request_checks(), udfører kontrol af lovligheden af anmodningen vedrørende diskindstillingerne. Anden - , som har en interessant udfordring :
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));
I den venter kernen på, at køen frigøres. Lad os måle forsinkelsen 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 | |
Det ser ud til, at vi er tæt på en løsning. De funktioner, der bruges til at fryse/ophæve en kø er и . De bruges, når det er nødvendigt at ændre indstillingerne for anmodningskøen, som potentielt er farlige for forespørgsler i denne kø. Når du ringer blk_mq_freeze_queue() fungere tælleren øges q->mq_frysedybde. Herefter venter kernen på, at køen tømmes .
Den tid, det tager at rydde denne kø, svarer til disklatens, da kernen venter på, at alle handlinger i køen er fuldført. Når køen er tom, anvendes indstillingsændringerne. Hvorefter det hedder , nedsættelse af tælleren fryse_dybde.
Nu ved vi nok til at rette op på situationen. Udevadm trigger-kommandoen får indstillingerne for blokenheden til at blive anvendt. Disse indstillinger er beskrevet i udev-reglerne. Vi kan finde ud af, hvilke indstillinger der fryser køen ved at prøve at ændre dem gennem sysfs eller ved at se på kernens kildekode. Vi kan også prøve BCC-værktøjet , som vil udsende kerne- og brugerrumsstackspor for hvert kald til terminalen blk_fryse_kø, for eksempel:
~# /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-reglerne ændres ret sjældent, og normalt sker dette på en kontrolleret måde. Så vi ser, at selv anvendelse af de allerede indstillede værdier forårsager en stigning i forsinkelsen i overførsel af anmodningen fra applikationen til disken. Det er selvfølgelig ikke en god praksis at generere udev-hændelser, når der ikke er ændringer i diskkonfigurationen (f.eks. er enheden ikke monteret/afbrudt). Vi kan dog hjælpe kernen med ikke at udføre unødvendigt arbejde og fryse anmodningskøen, hvis det ikke er nødvendigt. rette situationen.
Konklusion
eBPF er et meget fleksibelt og kraftfuldt værktøj. I artiklen så vi på en praktisk case og demonstrerede en lille del af, hvad der kan gøres. Hvis du er interesseret i at udvikle BCC-værktøjer, er det værd at tage et kig på , som beskriver det grundlæggende godt.
Der er andre interessante fejlfindings- og profileringsværktøjer baseret på eBPF. En af dem - , som giver dig mulighed for at skrive kraftfulde one-liners og små programmer i det akavede sprog. En anden - , giver dig mulighed for at indsamle lav-niveau, høj opløsning metrics direkte ind i din prometheus server, med mulighed for senere at få smukke visualiseringer og endda advarsler.
Kilde: www.habr.com