Linux har ett stort antal verktyg för att felsöka kärnan och applikationer. De flesta av dem har en negativ inverkan på applikationsprestanda och kan inte användas i produktionen.
För ett par år sedan fanns det - eBPF. Det gör det möjligt att spåra kärnan och användarapplikationer med låg overhead och utan att behöva bygga om program och ladda tredjepartsmoduler i kärnan.
Det finns redan många applikationsverktyg som använder eBPF, och i den här artikeln kommer vi att titta på hur du skriver ditt eget profileringsverktyg baserat på biblioteket . Artikeln är baserad på verkliga händelser. Vi går från problem till fix för att visa hur befintliga verktyg kan användas i specifika situationer.
Ceph är långsam
En ny värd har lagts till i Ceph-klustret. Efter att ha migrerat en del av datan till den märkte vi att hastigheten för att behandla skrivförfrågningar av den var mycket lägre än på andra servrar.
Till skillnad från andra plattformar använde denna värd bcache och den nya linux 4.15-kärnan. Detta var första gången en värd av denna konfiguration användes här. Och i det ögonblicket stod det klart att roten till problemet teoretiskt sett kunde vara vad som helst.
Undersöker värden
Låt oss börja med att titta på vad som händer i ceph-osd-processen. För detta kommer vi att använda и (mer om som du kan läsa ):
Bilden berättar att funktionen fdatasync() spenderade mycket tid på att skicka en förfrågan till funktioner generic_make_request(). Detta betyder att orsaken till problemen med största sannolikhet ligger någonstans utanför själva osd-demonen. Detta kan vara antingen kärnan eller diskar. Iostatutgången visade en hög latens i bearbetningsförfrågningar från bcache-diskar.
När vi kontrollerade värden upptäckte vi att systemd-udevd-demonen förbrukar en stor mängd CPU-tid - cirka 20% på flera kärnor. Detta är konstigt beteende, så du måste ta reda på varför. Eftersom Systemd-udevd arbetar med uevents, bestämde vi oss för att titta igenom dem udevadm monitor. Det visar sig att ett stort antal förändringshändelser genererades för varje blockenhet i systemet. Detta är ganska ovanligt, så vi måste titta på vad som genererar alla dessa händelser.
Använda BCC Toolkit
Som vi redan har upptäckt, spenderar kärnan (och ceph-demonen i systemanropet) mycket tid i generic_make_request(). Låt oss försöka mäta hastigheten på denna funktion. I Det finns redan ett underbart verktyg - funktionsförmåga. Vi kommer att spåra demonen med dess PID med ett intervall på 1 sekund mellan utdata och mata ut resultatet i millisekunder.
Denna funktion fungerar vanligtvis snabbt. Allt det gör är att skicka begäran till enhetsdrivrutinskön.
Bcache är en komplex enhet som faktiskt består av tre diskar:
- stödenhet (cachelagrad disk), i detta fall är det en långsam hårddisk;
- cachningsenhet (cachedisk), här är detta en partition av NVMe-enheten;
- den virtuella bcache-enheten som programmet körs med.
Vi vet att överföringen av begäran går långsamt, men för vilken av dessa enheter? Vi kommer att ta itu med detta lite senare.
Vi vet nu att händelser sannolikt kommer att orsaka problem. Att hitta exakt vad som orsakar deras generation är inte så lätt. Låt oss anta att detta är någon form av programvara som lanseras med jämna mellanrum. Låt oss se vilken typ av programvara som körs på systemet med hjälp av ett skript execsnoop från densamma . Låt oss köra det och skicka utdata till en fil.
Till exempel så här:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Vi kommer inte att visa hela produktionen av execsnoop här, men en rad av intresse för oss 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 övervakningssystemets konfiguration hittades felaktiga parametrar. Temperaturen på HBA-adaptern togs var 30:e sekund, vilket är mycket oftare än nödvändigt. Efter att ha ändrat kontrollintervallet till ett längre upptäckte vi att fördröjningstiden för förfrågningsbearbetning på denna värd inte längre stack ut jämfört med andra värdar.
Men det är fortfarande oklart varför bcache-enheten var så långsam. Vi förberedde en testplattform med en identisk konfiguration och försökte återskapa problemet genom att köra fio på bcache, periodvis köra udevadm trigger för att generera uevents.
Skriva BCC-baserade verktyg
Låt oss försöka skriva ett enkelt verktyg för att spåra och visa de långsammaste samtalen generic_make_request(). Vi är också intresserade av namnet på enheten som denna funktion kallades för.
Planen är enkel:
- Registrera kprobe på generic_make_request():
- Vi sparar disknamnet i minnet, tillgängligt via funktionsargumentet;
- Vi sparar tidsstämpeln.
- Registrera kretprobe för retur från generic_make_request():
- Vi får aktuell tidsstämpel;
- Vi letar efter den sparade tidsstämpeln och jämför den med den nuvarande;
- Om resultatet är större än det angivna, hittar vi det sparade disknamnet och visar det på terminalen.
Kprobes и kretprobes använd en brytpunktsmekanism för att ändra funktionskoden i farten. Du kan läsa и artikel om detta ämne. Om du tittar på koden för olika verktyg i , då kan du se att de har en identisk struktur. Så i den här artikeln kommer vi att hoppa över att analysera skriptargument och gå vidare till själva BPF-programmet.
eBPF-texten inuti python-skriptet ser ut så här:
bpf_text = “”” # Here will be the bpf program code “””
För att utbyta data mellan funktioner använder eBPF-program . Vi kommer att göra detsamma. Vi kommer att använda process-PID som nyckel och definiera strukturen som värdet:
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 hashtabell som heter p, med nyckeltyp u64 och ett typvärde struct data_t. Tabellen kommer att finnas tillgänglig i samband med vårt BPF-program. Makrot BPF_PERF_OUTPUT registrerar en annan anropad tabell händelser, som används för in i användarutrymmet.
När man mäter fördröjningar mellan att anropa en funktion och återvända från den, eller mellan anrop till olika funktioner, måste man ta hänsyn till att mottagna data måste tillhöra samma sammanhang. Med andra ord måste du komma ihåg om den eventuella parallella lanseringen av funktioner. Vi har förmågan att mäta latensen mellan att anropa en funktion i en process och att återvända från den funktionen i en annan process, men detta är sannolikt värdelöst. Ett bra exempel här skulle vara , där hashtabellnyckeln är inställd på en pekare till struct begäran, vilket återspeglar en diskbegäran.
Därefter måste vi skriva koden som kommer att köras när funktionen som studeras kallas:
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 det första argumentet för den anropade funktionen att ersättas som det andra argumentet . Efter detta får vi PID för processen i det sammanhang vi arbetar med, och den aktuella tidsstämpeln i nanosekunder. Vi skriver ner allt i ett nyvalt struct data_t data. Vi får disknamnet från strukturen bio, som skickas när du ringer generic_make_request(), och spara den i samma struktur datum. Det sista steget är att lägga till en post i hashtabellen som nämndes tidigare.
Följande funktion kommer att anropas vid retur 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 för processen och tidsstämpeln, men allokerar inte minne för den nya datastrukturen. Istället söker vi i hashtabellen efter en redan existerande struktur med nyckeln == aktuell PID. Om strukturen hittas tar vi reda på namnet på den pågående processen och lägger till den i den.
Det binära skiftet vi använder här behövs för att få tråden GID. de där. PID för huvudprocessen som startade tråden i det sammanhang som vi arbetar med. Funktionen vi kallar returnerar både trådens GID och dess PID i ett enda 64-bitars värde.
När vi skickar ut till terminalen är vi för närvarande inte intresserade av tråden, men vi är intresserade av huvudprocessen. Efter att ha jämfört den resulterande fördröjningen med en given tröskel passerar vi vår struktur datum in i användarutrymmet via tabell händelser, varefter vi raderar posten från p.
I python-skriptet som kommer att ladda den här koden måste vi ersätta MIN_US och FACTOR med fördröjningströskelvärdena och tidsenheterna, som vi kommer att skicka genom argumenten:
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 måste vi förbereda BPF-programmet via och registrera prover:
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 också bestämma struct data_t i vårt manus, annars kommer vi inte att kunna läsa någonting:
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 mata ut data till 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()
Själva skriptet finns på . Låt oss försöka köra det på en testplattform där fio kör, skriver till bcache och ringer udevadm monitor:
Till sist! Nu ser vi att det som såg ut som en stalling bcache-enhet faktiskt är ett stalling call generic_make_request() för en cachad disk.
Gräv ner i kärnan
Vad är det som saktar ner under förfrågan överföring? Vi ser att förseningen inträffar redan före start av förfrågningsredovisning, d.v.s. redovisning av en specifik begäran om ytterligare utmatning av statistik på den (/proc/diskstats eller iostat) har ännu inte påbörjats. Detta kan enkelt verifieras genom att köra iostat medan problemet reproduceras, eller , som baseras på början och slutet av förfrågningsredovisning. Inget av dessa verktyg kommer att visa problem för förfrågningar till den cachade disken.
Om vi tittar på funktionen generic_make_request(), då kommer vi att se att innan begäran börjar bokföras, anropas ytterligare två funktioner. Först - generic_make_request_checks(), utför kontroller av förfrågans legitimitet angående diskinställningarna. andra - , som har en intressant utmaning :
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 väntar kärnan på att kön ska lossna. Låt oss mäta förseningen 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 verkar som att vi är nära en lösning. Funktionerna som används för att frysa/avfrysa en kö är и . De används när det är nödvändigt att ändra inställningarna för förfrågningskön, vilket är potentiellt farligt för förfrågningar i denna kö. När du ringer blk_mq_freeze_queue() fungera räknaren ökas q->mq_frysa_djup. Efter detta väntar kärnan på att kön ska tömmas .
Tiden det tar att rensa denna kö motsvarar disklatens då kärnan väntar på att alla köade operationer ska slutföras. När kön är tom tillämpas inställningarna. Efter vilken den kallas , minskar räknaren freeze_depth.
Nu vet vi tillräckligt för att rätta till situationen. Kommandot udevadm trigger gör att inställningarna för blockenheten tillämpas. Dessa inställningar beskrivs i udev-reglerna. Vi kan hitta 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å prova BCC-verktyget , som kommer att mata ut kärn- och användarutrymmesstackspår för varje anrop till terminalen 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 på ett kontrollerat sätt. Så vi ser att även att tillämpa de redan inställda värdena orsakar en ökning i förseningen i överföringen av begäran från applikationen till disken. Naturligtvis är det inte en bra praxis att generera udev-händelser när det inte finns några ändringar i diskkonfigurationen (till exempel enheten inte är monterad/frånkopplad). Däremot kan vi hjälpa kärnan att inte göra onödigt arbete och frysa förfrågningskön om det inte är nödvändigt. rätta till situationen.
Slutsats
eBPF är ett mycket flexibelt och kraftfullt verktyg. I artikeln tittade vi på ett praktiskt fall och visade en liten del av vad som kan göras. Om du är intresserad av att utveckla BCC-verktyg är det värt att ta en titt på , som beskriver grunderna väl.
Det finns andra intressanta felsöknings- och profileringsverktyg baserade på eBPF. En av dem - , som låter dig skriva kraftfulla one-liners och små program på det awk-liknande språket. Annan - , låter dig samla in lågnivå, högupplöst mätvärde direkt i din prometheus-server, med möjligheten att senare få vackra visualiseringar och till och med varningar.
Källa: will.com