Linux huet eng grouss Unzuel vun Tools fir de Kernel an Uwendungen ze Debuggen. Déi meescht vun hinnen hunn en negativen Impakt op d'Applikatioun Leeschtung a kënnen net an der Produktioun benotzt ginn.
Virun e puer Joer gouf et - eBPF. Et mécht et méiglech de Kernel a Benotzerapplikatiounen mat nidderegen Overhead ze verfolgen an ouni d'Notzung fir Programmer opzebauen an Drëtt-Partei Moduler an de Kernel ze lueden.
Et gi scho vill Applikatiouns-Utilities déi eBPF benotzen, an an dësem Artikel wäerte mir kucken wéi Dir Ären eegene Profiling-Utility baséiert op der Bibliothéik . Den Artikel baséiert op realen Eventer. Mir ginn vum Problem fir ze fixéieren fir ze weisen wéi existent Utilities a spezifesche Situatioune kënne benotzt ginn.
Ceph ass lues
En neie Host gouf an de Ceph Cluster bäigefüügt. No der Migratioun vun e puer vun den Donnéeën, hu mir gemierkt datt d'Geschwindegkeet vun der Veraarbechtung vun der Schreiffuerderunge vill méi niddereg war wéi op anere Serveren.
Am Géigesaz zu anere Plattformen huet dësen Host bcache an den neie Linux 4.15 Kernel benotzt. Dëst war déi éischte Kéier datt e Host vun dëser Konfiguratioun hei benotzt gouf. An dee Moment war kloer, datt d'Wurzel vum Problem theoretesch alles kéint sinn.
Enquête vum Host
Loosst eis ufänken mat ze kucken wat am Ceph-osd Prozess geschitt. Fir dëst wäerte mir benotzen и (méi iwwer déi Dir kënnt liesen ):
D'Bild seet eis datt d'Funktioun fdatasync() vill Zäit verbruecht fir eng Ufro op Funktiounen ze schécken generic_make_request(). Dëst bedeit datt héchstwahrscheinlech d'Ursaach vun de Probleemer iergendwou ausserhalb vum osd Daemon selwer ass. Dëst kann entweder de Kernel oder Disks sinn. D'iostat Ausgang huet eng héich Latenz bei der Veraarbechtung vun Ufroe vu bcache Disks gewisen.
Wann Dir de Host iwwerpréift, hu mir festgestallt datt de systemd-udevd Daemon eng grouss Quantitéit vun der CPU Zäit verbraucht - ongeféier 20% op verschiddene Kären. Dëst ass komesch Verhalen, also musst Dir erausfannen firwat. Zanter Systemd-udevd Wierker mat uevents, mir decidéiert hinnen duerch ze kucken ausevadm Monitor. Et stellt sech eraus datt eng grouss Zuel vu Verännerungsevenementer fir all Blockapparat am System generéiert goufen. Dëst ass zimlech ongewéinlech, also musse mir kucken wat all dës Eventer generéiert.
Benotzt de BCC Toolkit
Wéi mir schonn erausfonnt hunn, verbréngt de Kernel (an de Ceph Daemon am Systemruff) vill Zäit an generic_make_request(). Loosst eis probéieren d'Geschwindegkeet vun dëser Funktioun ze moossen. IN Et gëtt schonn eng wonnerbar Utility - funclatency. Mir verfollegen den Daemon duerch säi PID mat engem 1 Sekonn Intervall tëscht Ausgängen an erausginn d'Resultat a Millisekonnen.
Dës Fonktioun funktionnéiert normalerweis séier. Alles wat et mécht ass d'Ufro un d'Device Chauffer Queue weiderginn.
Bcache ass e komplexen Apparat deen tatsächlech aus dräi Disken besteet:
- Backing Apparat (cache Scheif), an dësem Fall ass et eng lues HDD;
- Caching Apparat (Caching Disk), hei ass dëst eng Partition vum NVMe Apparat;
- de virtuellen Apparat bcache mat deem d'Applikatioun leeft.
Mir wëssen datt d'Ufroiwwerdroung lues ass, awer fir wéi eng vun dësen Apparater? Mir beschäftegen eis e bësse méi spéit.
Mir wëssen elo datt Ueventer méiglecherweis Probleemer verursaachen. Fannen wat genee hir Generatioun verursaacht ass net sou einfach. Loosst eis unhuelen datt dëst eng Zort Software ass déi periodesch lancéiert gëtt. Loosst eis kucken wéi eng Software um System mat engem Skript leeft execsnoop vun der selwechter . Loosst eis et lafen a schéckt d'Ausgab op eng Datei.
Zum Beispill esou:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Mir weisen net déi voll Ausgang vun execsnoop hei, awer eng Zeil vun Interesse fir eis huet esou ausgesinn:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Déi drëtt Kolonn ass den PPID (Elteren PID) vum Prozess. De Prozess mat PID 5802 huet sech als ee vun de Fuedem vun eisem Iwwerwaachungssystem erausgestallt. Wann Dir d'Konfiguratioun vum Iwwerwaachungssystem iwwerpréift, goufen falsch Parameteren fonnt. D'Temperatur vum HBA Adapter gouf all 30 Sekonnen geholl, wat vill méi dacks ass wéi néideg. Nodeems mir de Scheckintervall op e méi laang geännert hunn, hu mir festgestallt datt d'Latenz vun der Ufroveraarbechtung op dësem Host net méi am Verglach mat anere Hosten erausstinn.
Awer et ass nach ëmmer onkloer firwat de bcache Apparat sou lues war. Mir hunn eng Testplattform mat enger identescher Konfiguratioun virbereet a probéiert de Problem ze reproduzéieren andeems Dir fio op bcache leeft, periodesch leeft udevadm Ausléiser fir uevents ze generéieren.
Schreiwen BCC-baséiert Tools
Loosst eis probéieren en einfachen Utility ze schreiwen fir déi luesst Uriff ze verfolgen an ze weisen generic_make_request(). Mir sinn och interesséiert fir den Numm vum Drive fir deen dës Funktioun genannt gouf.
De Plang ass einfach:
- Umeldung kprobe op generic_make_request():
- Mir späicheren den Disk Numm an d'Erënnerung, zougänglech duerch d'Funktiounsargument;
- Mir späicheren den Zäitstempel.
- Umeldung kretprobe fir zréck aus generic_make_request():
- Mir kréien den aktuellen Zäitstempel;
- Mir kucken fir de gespäichert Zäitstempel a vergläichen et mat der aktueller;
- Wann d'Resultat méi grouss ass wéi de spezifizéierte, fanne mir de gespäicherten Disknumm a weisen en um Terminal.
Kprobes и kretprobes benotzen engem breakpoint Mechanismus Funktioun Code op der fléien änneren. Dir kënnt liesen и Artikel zu dësem Thema. Wann Dir de Code vu verschiddenen Utilities kuckt an , da kënnt Dir gesinn datt se eng identesch Struktur hunn. Also an dësem Artikel wäerte mir d'Parsing vun Skript Argumenter iwwersprangen a weider op de BPF Programm selwer goen.
Den eBPF Text am Python Skript gesäit esou aus:
bpf_text = “”” # Here will be the bpf program code “””
Fir Daten tëscht Funktiounen auszetauschen, benotzen eBPF Programmer . Mir wäerten déi selwecht maachen. Mir benotzen de Prozess PID als Schlëssel, an definéieren d'Struktur als de Wäert:
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);
Hei registréiere mir en Hash Dësch genannt p, mat Schlëssel Typ u64 an e Wäert vun Typ struct daten_t. Den Dësch wäert am Kontext vun eisem BPF Programm verfügbar sinn. De BPF_PERF_OUTPUT Makro registréiert eng aner Tabell genannt Manifestatioune, déi benotzt gëtt fir an de Benotzerraum.
Wann Dir Verspéidungen moosst tëscht engem Opruff vun enger Funktioun an zréck dovunner, oder tëscht Uriff op verschidde Funktiounen, musst Dir Rechnung droen datt déi kritt Donnéeën zum selwechte Kontext gehéieren. An anere Wierder, Dir musst iwwer déi méiglech Parallelstart vu Funktiounen erënneren. Mir hunn d'Fäegkeet d'Latenz ze moossen tëscht enger Funktioun am Kontext vun engem Prozess ze ruffen an zréck vun där Funktioun am Kontext vun engem anere Prozess, awer dëst ass méiglecherweis nëtzlos. E gutt Beispill hei wier , wou den Hash-Tabelleschlëssel op e Pointer gesat gëtt struct Ufro, déi eng Diskufro reflektéiert.
Als nächst musse mir de Code schreiwen, dee leeft wann d'Funktioun ënner Studie genannt gëtt:
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);
}
Hei gëtt dat éischt Argument vun der genannter Funktioun als zweet Argument ersat . Duerno kréie mir de PID vum Prozess am Kontext vun deem mir schaffen, an den aktuellen Zäitstempel an Nanosekonnen. Mir schreiwen alles an engem frësch ausgewielten struct data_t daten. Mir kréien den Disk Numm vun der Struktur Bio, dee beim Uruff passéiert gëtt generic_make_request(), a späichert et an der selwechter Struktur Donnéeën. De leschte Schrëtt ass eng Entrée an den Hash-Tabellen ze addéieren déi virdru erwähnt gouf.
Déi folgend Funktioun gëtt op Retour vum genannt 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);
}
}
Dës Funktioun ass ähnlech wéi déi virdru: mir fannen de PID vum Prozess an den Zäitstempel eraus, awer allokéiere keng Erënnerung fir déi nei Datestruktur. Amplaz sichen mir den Hash-Tabelle fir eng scho existent Struktur mam Schlëssel == aktuell PID. Wann d'Struktur fonnt gëtt, fanne mir den Numm vum lafende Prozess eraus a fügen se derbäi.
Déi binär Verréckelung déi mir hei benotzen ass gebraucht fir de Fuedem GID ze kréien. déi. PID vum Haaptprozess deen de Fuedem ugefaang huet am Kontext vun deem mir schaffen. D'Funktioun déi mir nennen gëtt souwuel de GID vum thread wéi och säi PID an engem eenzegen 64-Bit Wäert zréck.
Wann Dir op den Terminal erausgëtt, si mir de Moment net un de Stroum interesséiert, awer mir sinn am Haaptprozess interesséiert. Nodeems mir déi resultéierend Verzögerung mat enger bestëmmter Schwell vergläicht, passéiere mir eis Struktur Donnéeën an Benotzer Raum via Dësch Manifestatioune, no deem mir d'Entrée läschen aus p.
Am Python Skript, deen dëse Code lued, musse mir MIN_US a FACTOR mat de Verzögerungsschwellen an Zäitunitéiten ersetzen, déi mir duerch d'Argumenter passéieren:
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"
Elo musse mir de BPF Programm virbereeden via a registréiert Proben:
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")
Mir mussen och bestëmmen struct daten_t an eisem Skript, soss kënne mir näischt liesen:
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)]
De leschte Schrëtt ass d'Donnéeën op den Terminal auszeginn:
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()
De Skript selwer ass verfügbar op . Loosst eis probéieren et op enger Testplattform auszeféieren wou fio leeft, schreift op bcache, a rufft udevadm Monitor:
Endlech! Elo gesi mir datt wat ausgesäit wéi e stalling bcache-Apparat ass tatsächlech e stalling Call generic_make_request() fir eng cache Scheif.
Gruef an de Kernel
Wat genee verlangsamt wärend der Ufroiwwerdroung? Mir gesinn, datt d'Verspéidung geschitt och virum Ufank vun Ufro Comptablesmethod, d.h. Comptablesmethod vun enger spezifescher Ufro fir weider Ausgab vu Statistiken doriwwer (/proc/diskstats oder iostat) huet nach net ugefaang. Dëst kann einfach verifizéiert ginn andeems Dir iostat leeft wärend de Problem reproduzéieren, oder , déi baséiert op den Ufank an Enn vun Ufro Comptablesmethod. Keen vun dësen Utilities wäert Problemer fir Ufroen op de cache Disk weisen.
Wa mir d'Funktioun kucken generic_make_request(), da wäerte mir gesinn datt ier d'Ufro ufänkt mat der Comptabilitéit, ginn zwou weider Funktiounen genannt. Éischten - generic_make_request_checks(), mécht Kontrollen iwwer d'Legitimitéit vun der Ufro iwwer d'Disk Astellunge. Zweeten - , déi eng interessant Erausfuerderung huet :
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));
Dobäi waart de Kernel op d'Schlaang fir unzefroen. Loosst eis d'Verspéidung moossen 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 | |
Et gesäit aus wéi wann mir no bei enger Léisung sinn. D'Funktioune benotzt fir eng Schlaang ze afréieren / unfreeze sinn и . Si gi benotzt wann et néideg ass d'Astellunge vun der Ufroschlaang z'änneren, déi potenziell geféierlech sinn fir Ufroen an dëser Schlaang. Beim Opruff blk_mq_freeze_queue() Funktioun de Comptoir gëtt erhéicht q->mq_freeze_depth. Duerno waart de Kernel fir datt d'Schlaang eidel ass .
D'Zäit déi et dauert fir dës Schlaang ze läschen ass gläich wéi d'Disklatenz wéi de Kernel waart op all Schlaangoperatioune fir ze kompletéieren. Wann d'Schlaang eidel ass, ginn d'Astellungsännerungen ugewannt. Duerno gëtt et genannt , Ofsenkung vum Comptoir freeze_depth.
Elo wësse mer genuch fir d'Situatioun ze korrigéieren. Den udevadm Trigger Kommando verursaacht d'Astellunge fir de Blockapparat applizéiert. Dës Astellunge sinn an der udev Regelen beschriwwen. Mir kënnen erausfannen wéi eng Astellungen d'Schlaang afréieren andeems Dir probéiert se duerch sysfs z'änneren oder andeems Dir de Kernel Quellcode kuckt. Mir kënnen och de BCC Utility probéieren , déi Kernel a Userspace Stack Spure fir all Uruff un den Terminal ausginn blk_freeze_queue, zum Beispill:
~# /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 Regelen änneren zimlech selten an normalerweis geschitt dat op eng kontrolléiert Manéier. Also gesi mir datt och d'Applikatioun vun de scho festgeluechte Wäerter e Spike an der Verzögerung verursaacht fir d'Ufro vun der Applikatioun op den Disk ze transferéieren. Natierlech, generéieren udev Evenementer wann et keng Ännerungen an der Scheif Configuratioun sinn (Zum Beispill, den Apparat ass net montéiert / disconnected) ass net eng gutt Praxis. Wéi och ëmmer, mir kënnen dem Kernel hëllefen net onnéideg Aarbecht ze maachen an d'Ufroschlaang afréieren wann et net néideg ass. d'Situatioun korrigéieren.
Konklusioun
eBPF ass e ganz flexibel a mächtegt Tool. Am Artikel hu mir ee praktesche Fall gekuckt an e klengen Deel vun deem wat gemaach ka ginn. Wann Dir interesséiert sidd fir BCC Utilities z'entwéckelen, ass et derwäert ze kucken , déi d'Grondlage gutt beschreiwen.
Et ginn aner interessant Debugging- a Profiléierungsinstrumenter baséiert op eBPF. Ee vun hinnen - , wat Iech erlaabt mächteg One-Liner a kleng Programmer an der awk-ähnlecher Sprooch ze schreiwen. Eng aner - , erlaabt Iech Low-Level, High-Resolution Metriken direkt an Äre Prometheus-Server ze sammelen, mat der Fäegkeet fir spéider schéi Visualiséierungen a souguer Alarmer ze kréien.
Source: will.com