A Linux számos eszközzel rendelkezik a kernel és az alkalmazások hibakeresésére. Legtöbbjük negatív hatással van az alkalmazások teljesítményére, és nem használhatók termelésben.
Pár éve volt - eBPF. Lehetővé teszi a kernel és a felhasználói alkalmazások nyomon követését alacsony ráfordítással, anélkül, hogy újra kellene építeni programokat és harmadik féltől származó modulokat kellene betölteni a kernelbe.
Már sok alkalmazási segédprogram használja az eBPF-et, és ebben a cikkben megvizsgáljuk, hogyan írhat saját profilozó segédprogramot a könyvtár alapján. . A cikk valós eseményeken alapul. Problémáról javításra haladunk, hogy megmutassuk, hogyan használhatók a meglévő segédprogramok bizonyos helyzetekben.
Ceph lassú
Új gazdagép került a Ceph-fürtbe. Az adatok egy részének áttelepítése után azt vettük észre, hogy az írási kérések feldolgozásának sebessége jóval alacsonyabb, mint más szervereken.
Más platformokkal ellentétben ez a gazdagép a bcache-t és az új linux 4.15-ös kernelt használta. Ez volt az első alkalom, hogy itt használták ennek a konfigurációnak a gazdagépét. És abban a pillanatban világossá vált, hogy a probléma gyökere elméletileg bármi lehet.
A házigazda nyomozása
Kezdjük azzal, hogy megnézzük, mi történik a ceph-osd folyamaton belül. Erre fogjuk használni и (erről bővebben olvashatsz ):
A kép azt mutatja, hogy a funkció fdatasync() sok időt töltött azzal, hogy kérést küldjön a funkcióknak generic_make_request(). Ez azt jelenti, hogy a problémák oka valószínűleg valahol magán az osd démonon kívül van. Ez lehet a kernel vagy a lemezek. Az iostat kimenete magas késleltetést mutatott a bcache lemezek kérelmeinek feldolgozásakor.
A gazdagép ellenőrzése során azt találtuk, hogy a systemd-udevd démon nagy mennyiségű CPU-időt fogyaszt – több magon körülbelül 20%-ot. Ez furcsa viselkedés, ezért meg kell találnia, miért. Mivel a Systemd-udevd ueventekkel működik, úgy döntöttünk, hogy végignézzük őket udevadm monitor. Kiderült, hogy a rendszer minden egyes blokkeszközéhez nagyszámú változási esemény generálódott. Ez meglehetősen szokatlan, ezért meg kell vizsgálnunk, mi generálja ezeket az eseményeket.
A BCC Toolkit használata
Mint már megtudtuk, a kernel (és a ceph démon a rendszerhívásban) sok időt tölt generic_make_request(). Próbáljuk meg mérni ennek a függvénynek a sebességét. BAN BEN Már van egy csodálatos segédprogram - funkcionalitás. A démont a PID alapján követjük nyomon, a kimenetek között 1 másodperces időközzel, és ezredmásodpercben adjuk ki az eredményt.
Ez a funkció általában gyorsan működik. Mindössze annyit tesz, hogy átadja a kérést az eszközillesztő-sornak.
Bcache egy összetett eszköz, amely valójában három lemezből áll:
- háttéreszköz (gyorsítótárazott lemez), ebben az esetben lassú HDD-ről van szó;
- gyorsítótárazó eszköz (gyorsítótár), itt ez az NVMe eszköz egyik partíciója;
- a bcache virtuális eszköz, amellyel az alkalmazás fut.
Tudjuk, hogy a kérések átvitele lassú, de ezek közül melyik készülék esetében? Ezzel egy kicsit később foglalkozunk.
Ma már tudjuk, hogy az események valószínűleg problémákat okoznak. Nem olyan egyszerű megtalálni, hogy pontosan mi okozza a generációjukat. Tételezzük fel, hogy ez valamiféle szoftver, amely rendszeresen indul. Nézzük meg, milyen szoftver fut a rendszeren script segítségével execsnoop ugyanabból . Futtassuk és küldjük el a kimenetet egy fájlba.
Például így:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Itt nem mutatjuk meg az execsnoop teljes kimenetét, de egy számunkra érdekes sor így nézett ki:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
A harmadik oszlop a folyamat PPID-je (parent PID). A PID 5802-es folyamat a megfigyelőrendszerünk egyik szálának bizonyult. A felügyeleti rendszer konfigurációjának ellenőrzésekor hibás paramétereket találtunk. A HBA adapter hőmérsékletét 30 másodpercenként mértük, ami sokkal gyakrabban van a szükségesnél. Miután az ellenőrzési intervallumot hosszabbra cseréltük, azt találtuk, hogy a kérésfeldolgozási késleltetés ezen a gazdagépen már nem tűnik ki a többi gazdagéphez képest.
De továbbra sem világos, miért volt olyan lassú a bcache eszköz. Elkészítettünk egy tesztplatformot azonos konfigurációval, és megpróbáltuk reprodukálni a problémát a fio futtatásával a bcache-n, időnként futtatva az udevadm triggert az uevent generálásához.
BCC-alapú eszközök írása
Próbáljunk meg írni egy egyszerű segédprogramot a leglassabb hívások nyomon követésére és megjelenítésére generic_make_request(). Érdekel minket a meghajtó neve is, amelyre ezt a funkciót hívták.
A terv egyszerű:
- Regisztráció kprobe on generic_make_request():
- A lemez nevét a memóriába mentjük, amely a függvény argumentumán keresztül érhető el;
- Mentjük az időbélyeget.
- Regisztráció kretprobe innen való visszatéréshez generic_make_request():
- Megkapjuk az aktuális időbélyeget;
- Megkeressük az elmentett időbélyeget, és összehasonlítjuk a jelenlegivel;
- Ha az eredmény nagyobb, mint a megadott, akkor megtaláljuk a mentett lemez nevét, és megjelenítjük a terminálon.
Kprobes и kretszondák töréspont-mechanizmussal módosíthatja a funkciókódot menet közben. Te tudsz olvasni и cikk ebben a témában. Ha megnézed a különböző segédprogramok kódját , akkor láthatja, hogy azonos szerkezetűek. Tehát ebben a cikkben kihagyjuk a szkriptargumentumok elemzését, és áttérünk magára a BPF programra.
A python szkripten belüli eBPF szöveg így néz ki:
bpf_text = “”” # Here will be the bpf program code “””
A függvények közötti adatcseréhez az eBPF programok használják . Mi is ezt fogjuk tenni. Kulcsként a folyamat PID-t fogjuk használni, értékként pedig a struktúrát definiáljuk:
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);
Itt regisztrálunk egy hash táblát p, kulcstípussal u64 és egy típusérték struct data_t. A táblázat a BPF programunk keretében lesz elérhető. A BPF_PERF_OUTPUT makró egy másik nevű táblát regisztrál események, amelyet arra használnak felhasználói térbe.
A függvény hívása és az onnan való visszatérés, illetve a különböző függvények hívásai közötti késések mérésekor figyelembe kell venni, hogy a kapott adatoknak ugyanabba a kontextusba kell tartozniuk. Más szóval, emlékeznie kell a funkciók lehetséges párhuzamos indítására. Lehetőségünk van mérni a késleltetést egy függvénynek egy folyamat kontextusában való meghívása és a függvényből egy másik folyamat kontextusában való visszatérése között, de ez valószínűleg haszontalan. Itt lenne egy jó példa , ahol a hash tábla kulcsa egy mutatóra van állítva struct kérés, amely egy lemezkérést tükröz.
Ezután meg kell írnunk azt a kódot, amely a vizsgált függvény meghívásakor fog futni:
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);
}
Itt a hívott függvény első argumentuma lesz helyettesítve második argumentumként . Ezt követően megkapjuk annak a folyamatnak a PID-jét, amelynek kontextusában dolgozunk, és az aktuális időbélyeget nanoszekundumban. Mindent leírunk egy frissen válogatott struct data_t data. A lemez nevét a szerkezetből kapjuk bio, amelyet híváskor átadnak generic_make_request(), és mentse el ugyanabban a struktúrában dátum. Az utolsó lépés egy bejegyzés hozzáadása a hash táblához, amelyet korábban említettünk.
A következő függvény lesz meghívva visszatéréskor 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);
}
}
Ez a funkció hasonló az előzőhöz: megtudjuk a folyamat PID-jét és időbélyegét, de nem foglalunk memóriát az új adatszerkezethez. Ehelyett a hash táblában egy már létező struktúrát keresünk a == aktuális PID kulcs használatával. Ha megtaláltuk a struktúrát, akkor kiderítjük a futó folyamat nevét és hozzáadjuk.
Az itt használt bináris eltolás szükséges a szál GID eléréséhez. azok. Annak a fő folyamatnak a PID-je, amely elindította azt a szálat, amelynek kontextusában dolgozunk. Az általunk meghívott függvény visszaadja a szál GID-jét és PID-jét is egyetlen 64 bites értékben.
A terminálra történő kiadáskor jelenleg nem a szál, hanem a fő folyamat érdekel bennünket. Miután a kapott késleltetést összevettük egy adott küszöbértékkel, átadjuk a struktúránkat dátum táblázaton keresztül a felhasználói térbe események, utána töröljük a bejegyzést p.
A kódot betöltõ python szkriptben a MIN_US és a FACTOR értéket le kell cserélnünk a késleltetési küszöbértékekkel és az idõegységekkel, amelyeket átadunk az argumentumokon:
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"
Most el kell készítenünk a BPF programot keresztül és regisztráljon mintákat:
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")
Azt is meg kell határoznunk struct data_t a forgatókönyvünkben, különben nem fogunk tudni olvasni semmit:
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)]
Az utolsó lépés az adatok kimenete a terminálra:
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()
Maga a forgatókönyv a címen érhető el . Próbáljuk meg futtatni egy tesztplatformon, ahol a fio fut, ír a bcache-be, és hívjuk meg az udevadm monitort:
Végül! Most látjuk, hogy ami úgy nézett ki, mint egy elakadt bcache eszköz, az valójában egy elakadt hívás generic_make_request() gyorsítótárazott lemezhez.
Vágj bele a kernelbe
Pontosan mi lassul le a kérés átvitele közben? Azt látjuk, hogy a késedelem még a kérés elszámolás megkezdése előtt jelentkezik, pl. a további statisztikai adatok (/proc/diskstats vagy iostat) kiadására irányuló konkrét kérés elszámolása még nem kezdődött el. Ez könnyen ellenőrizhető az iostat futtatásával a probléma reprodukálása közben, ill , amely a kérelem elszámolásának kezdete és vége alapján történik. Ezen segédprogramok egyike sem mutat problémákat a gyorsítótárazott lemezre irányuló kérések esetén.
Ha a függvényt nézzük generic_make_request(), akkor látni fogjuk, hogy a kérés elszámolásának megkezdése előtt még két függvény kerül meghívásra. Első - generic_make_request_checks(), ellenőrzi a lemezbeállításokkal kapcsolatos kérés jogosságát. Második - , amelynek érdekes kihívása van :
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));
Ebben a kernel arra vár, hogy a sor lefagyjon. Mérjük meg a késést 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 | |
Úgy tűnik, közel járunk a megoldáshoz. A várólista rögzítésére/feloldására használt funkciók a következők и . Akkor használatosak, ha módosítani kell a kérési sor beállításait, amelyek potenciálisan veszélyesek az ebben a sorban lévő kérésekre. Híváskor blk_mq_freeze_queue() funkció a számláló növekszik q->mq_fagy_mélység. Ezt követően a kernel megvárja, amíg a sor kiürül .
A sor törléséhez szükséges idő megegyezik a lemez késleltetésével, mivel a kernel megvárja az összes sorba állított művelet befejezését. Ha a sor kiürült, a beállítások módosításai érvényesek. Ami után úgy hívják , csökkenti a számlálót fagyasztási_mélység.
Most már eleget tudunk a helyzet javításához. Az udevadm trigger parancs a blokkeszköz beállításait alkalmazza. Ezeket a beállításokat az udev szabályok írják le. Megtudhatjuk, hogy mely beállítások fagyasztják be a sort, ha megpróbáljuk megváltoztatni őket sysfs-en keresztül, vagy megnézzük a kernel forráskódját. Kipróbálhatjuk a BCC segédprogramot is , amely a terminál minden egyes hívásánál kernel- és felhasználóiterület-veremnyomkövetést ad ki blk_freeze_queue, például:
~# /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]
Az Udev-szabályok meglehetősen ritkán változnak, és ez általában ellenőrzött módon történik. Tehát azt látjuk, hogy még a már beállított értékek alkalmazása is késlelteti a kérés átvitelét az alkalmazásból a lemezre. Természetesen nem jó gyakorlat az udev események generálása, amikor nincs változás a lemez konfigurációjában (például az eszköz nincs csatlakoztatva/leválasztva). Segíthetünk azonban abban, hogy a kernel ne végezzen felesleges munkát, és ha nem szükséges, lefagyasztjuk a kérési sort. korrigálja a helyzetet.
Következtetés
Az eBPF egy nagyon rugalmas és hatékony eszköz. A cikkben egy gyakorlati esetet néztünk meg, és bemutattuk annak egy kis részét, hogy mit lehet tenni. Ha érdekel a BCC segédprogramok fejlesztése, érdemes egy pillantást vetni rá , amely jól leírja az alapokat.
Vannak más érdekes hibakereső és profilozó eszközök is az eBPF-en. Egyikük - , amely lehetővé teszi erőteljes egysoros szövegek és kis programok írását az awk-szerű nyelven. Egy másik - , lehetővé teszi, hogy alacsony szintű, nagy felbontású mérőszámokat gyűjtsön közvetlenül a prometheus szerverére, így később gyönyörű vizualizációkat és akár figyelmeztetéseket is kaphat.
Forrás: will.com