Es gibt viele Tools zum Debuggen von Kernel- und Userspace-Programmen unter Linux. Die meisten von ihnen haben Auswirkungen auf die Leistung und können nicht einfach in Produktionsumgebungen ausgeführt werden. Vor einigen Jahren wurde eBPF
entwickelt , mit dem der Kernel und der Benutzerbereich mit geringem Overhead verfolgt werden können, ohne dass Programme neu kompiliert oder Kernelmodule geladen werden müssen.
Es gibt jetzt viele Tools, die eBPF verwenden. In diesem Artikel wird erläutert, wie Sie Ihr eigenes Profiling-Tool mithilfe der
PythonBCC-Bibliothek schreiben. Dieser Artikel basiert auf einem echten Problem aus der Produktionsumgebung. Wir werden Sie durch die Lösung des Problems führen und zeigen, wie vorhandene bcc-Tools in einigen Fällen verwendet werden können.
Ceph ist langsam
Eine neue Plattform wurde einem Ceph-Cluster hinzugefügt. Nach der Migration einiger Daten auf die Plattform war die Latenz für Schreibanforderungen höher als auf den anderen Servern.
Diese Plattform verfügt über ein neues virtuelles Caching-Gerät - bcache, das wir in diesem Cluster noch nicht verwendet haben - und einen neuen Kernel - 4.15, der noch nirgendwo anders in diesem Cluster verwendet wird. Die Wurzel des Problems könnte überall liegen, also schauen wir uns das genauer an.
Untersuchung des Gastgebers
Schauen wir uns an, was im ceph-osd-Prozess vor sich geht. Wir verwenden das Verfolgungswerkzeug
perf und
flamescope , um Flammengraphen zu erstellen:
Wie aus dem Flammengraphen hervorgeht, hat
fdatasync () viel Zeit damit verbracht, Bio in der Funktion
generic_make_request () einzureichen . Daher liegt die Wurzel unseres Problems irgendwo außerhalb des Ceph-Daemons. Möglicherweise handelt es sich um ein Kernel-, Bcache- oder Festplattenproblem. Die iostat-Ausgabe zeigte eine hohe Latenz für bcache-Geräte.
Ein weiterer verdächtiger Befund ist, dass der systemd-udevd-Daemon CPU verbraucht. ca. 20% auf mehreren CPUs. Das ist seltsames Verhalten, also müssen wir herausfinden, was los ist. Da systemd-udevd mit uevents zusammenarbeitet, müssen wir den
udevadm-Monitor verwenden , um herauszufinden, ob im System uevents vorhanden sind. Nach der Überprüfung haben wir festgestellt, dass für jedes Blockgerät im System viele "Änderungsereignisse" generiert wurden.
Dies ist ungewöhnlich, daher werden wir herausfinden, warum all diese Ereignisse gesendet werden.
Verwenden des BCC Toolkit
Wie wir bereits wissen, verbringt der Kernel (und der Ceph-Daemon) viel Zeit mit der Ausführung von
generic_make_requst () -Funktionen. Lassen Sie uns die Latenz mithilfe der
Funclatency aus dem
BCC-Toolkit messen, um sicherzustellen, dass wir auf dem richtigen Weg sind. Wir verfolgen die PID (-p) des Ceph-Daemons in Intervallen von 1 Sekunde (-i) und drucken die Latenz in Millisekunden (-m).
Diese Funktion arbeitet normalerweise sehr schnell. Es wird lediglich die Biostruktur an die Warteschlange des Gerätetreibers gesendet.
Bcache ist ein komplexes Gerät. Tatsächlich besteht es aus 3 Geräten: einem Sicherungsgerät, das in unserem Fall eine langsame Festplatte ist; ein Caching-Gerät, bei dem es sich um die Partition des NVMe-Laufwerks handelt; und ein virtuelles bcache-Gerät, das von der Anwendung verwendet wird. Wir wissen, dass die Übermittlung langsam ist, aber für welches Gerät? Dies ist etwas, worauf wir später noch eingehen werden.
Im Moment wissen wir, dass Ereignisse Ereignisse in Ceph-Dämonen verursachen, und wir müssen die Software finden, die Ereignisse auslöst. Es ist nicht einfach zu finden, welche Ursachen Ereignisse verursachen. Wir gehen davon aus, dass es sich um Software handelt, die nur in regelmäßigen Abständen ausgeführt wird. Um zu sehen, was auf dem System ausgeführt wird, verwenden wir
execsnoop aus dem BCC-Toolkit. Wir können es ausführen und
stdout in eine Datei umleiten.
Zum Beispiel:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Wir werden hier nicht die vollständige Execsnoop-Ausgabe geben, aber eine interessante Zeichenfolge, die wir dort gefunden haben, war:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/'
Die dritte Spalte ist die PPID des Prozesses. Wir haben überprüft, was 5802 ist, und festgestellt, dass es sich um einen unserer Überwachungs-Daemon-Threads handelt. Bei näherer Betrachtung der Konfiguration des Überwachungssystems haben wir einen fehlerhaften Parameter gefunden. Die HBA-Temperatur wurde alle 30 Sekunden abgerufen, was zu oft ist. Nachdem wir das Prüfintervall auf einen angemesseneren Wert geändert hatten, stellten wir fest, dass unsere Ceph-Latenz mit den anderen Plattformen übereinstimmte.
Wir wissen aber immer noch nicht, warum die Bcache-Latenz hoch war. Wir haben eine Testplattform mit derselben Konfiguration eingerichtet und versucht, das Problem mit fio auf dem bcache-Gerät zu reproduzieren, während wir gleichzeitig udev mit dem Befehl udevadm trigger auslösen.
Schreiben von BCC-basierten Tools
Was wir hier tun werden, ist ein einfaches Tool zu schreiben, das die langsamsten generic_make_request () -Aufrufe verfolgt und den Namen der Festplatte druckt, für die die Funktion aufgerufen wurde.
Der Plan ist einfach:
- Registrieren Sie kprobe auf generic_make_request () :
- Speichern Sie den im Argument der Funktion verfügbaren Datenträgernamen
- Speichern Sie den aktuellen Zeitstempel
- Registrieren Sie kretprobe in der return-Anweisung generic_make_request () :
- Rufen Sie den aktuellen Zeitstempel ab
- Suchen Sie nach zuvor gespeicherten Zeitstempeln und vergleichen Sie diese mit den aktuellen
- Wenn das Ergebnis höher als der Schwellenwert ist, suchen Sie nach zuvor gespeicherten Datenträgernamen und drucken Sie diese mit zusätzlichen Informationen auf dem Terminal aus
Kprobes und
kretprobes verwenden Haltepunkte, um den Code einer Funktion zur Laufzeit zu ändern. Hier finden Sie
Dokumentation sowie einen guten
Artikel dazu. Wenn Sie sich den Code für verschiedene
BCC-Tools ansehen, werden Sie feststellen, dass alle eine identische Struktur haben. Wir überspringen das Parsen von Argumenten und konzentrieren uns auf das BPF-Programm selbst.
Der Text unseres Programms wird in Python wie folgt definiert:
bpf_text = “””
BPF-Programme verwenden
Hashmaps , um Daten zwischen verschiedenen Funktionen
auszutauschen . Wir werden PID als Schlüssel und eine selbst definierte Struktur als Wert verwenden.
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);
Hier registrieren wir eine Hashmap namens
p mit einem
u64- Schlüsseltyp und einem
struct data_t-Werttyp . Diese Karte ist über unseren BPF-Programmkontext zugänglich. Das Makro
BPF_PERF_OUTPUT registriert eine andere Zuordnung namens
Ereignisse , mit der
Daten in den Benutzerbereich übertragen werden.
Wenn Sie die Latenz zwischen dem Funktionsaufruf und seiner Rückgabe oder zwischen einem Funktionsaufruf und einem anderen messen, müssen Sie sicherstellen, dass sich die Daten, die Sie gespeichert haben und auf die Sie später zugreifen, auf denselben Kontext beziehen. Mit anderen Worten, Sie müssen alle anderen parallelen Ausführungen derselben Funktion kennen. Es ist möglich, die Latenz zwischen dem Funktionsaufruf eines Prozesses und den Rückgaben derselben Funktion von einem anderen Prozess zu verfolgen, aber das hilft uns nicht. Ein gutes Beispiel ist das
Biolatency-Tool, bei dem der Zeiger auf die
Strukturanforderung als Hashmap-Schlüssel verwendet wird.
Als nächstes müssen wir einen Code schreiben, der bei Funktionsaufrufen über einen kprobe-Mechanismus ausgeführt wird:
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); }
Hier haben wir das erste
Argument generic_make_request () als zweites Argument unserer Funktion. Dann erhalten wir die PID und den aktuellen Zeitstempel in Nanosekunden und schreiben sie in die neu zugewiesenen
struct data_t-Daten . Wir erhalten den Datenträgernamen aus der
Biostruktur , die an
generic_make_request () übergeben wird , und speichern ihn in unseren
Daten . Der letzte Schritt besteht darin, der zuvor beschriebenen Hashmap einen Eintrag hinzuzufügen.
Diese Funktion wird ausgeführt,
wenn generic_make_request () Folgendes zurückgibt:
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); } }
Wir erhalten die PID und den Zeitstempel von der vorherigen Ausgabe und suchen in der Hashmap nach dem Wert, bei dem
key == current PID ist . Wenn es gefunden wird, erhalten wir den Namen des laufenden Prozesses und fügen ihn der
Datenstruktur hinzu . Was wir hier mit
data-> pid machen , gibt uns die Thread-Gruppen-ID. Die zuvor aufgerufene
Funktion bpf_get_current_pid_tgid () gibt die Thread-GID und -PID des Prozesses in demselben 64-Bit-Wert zurück.
Wir sind nicht an der ID jedes Threads interessiert, aber wir möchten die PID des Hauptthreads kennen. Nachdem wir überprüft haben, ob die Latenz über dem Schwellenwert liegt, senden wir unsere
Datenstruktur über die
Ereigniskarte an den Benutzerbereich und löschen am Ende den Hashmap-Eintrag.
In unserem Python-Skript müssen wir
MIN_US und
FACTOR entsprechend dem gewünschten Schwellenwert und der Zeiteinheit ersetzen, die wir in unserem Ergebnis sehen möchten:
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"
Dann müssen wir das BPF-Programm mit einem
BPF () -Makro vorbereiten und Sonden registrieren:
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")
Wir müssen auch die gleiche Struktur wie
struct data_t in unserem Skript definieren, um die Daten aus dem BPF-Programm zu lesen:
TASK_COMM_LEN = 16
Der letzte Schritt besteht darin, die gewünschten Daten auszudrucken:
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)
Das vollständige Skript ist auf
GitHub verfügbar. Lassen Sie uns das Skript ausführen und udev-Ereignisse auslösen, während fio auf ein bcache-Gerät schreibt:
Erfolg! Jetzt sehen wir, dass eine hohe Latenz für bcache die
generische Latenz von
make_request () für das Sicherungsgerät ist.
Grabe dich in den Kernel
Was zieht sich bei der Einreichung von Anfragen hin? Wir sehen, dass eine Latenzspitze aufgetreten ist, bevor die Anforderungsabrechnung überhaupt gestartet wurde. Dies kann leicht überprüft werden, indem entweder iostat während des Problems oder das
Biolatency-BCC-Skript ausgeführt wird , das auf dem Start der Abrechnungsanforderung basiert, sodass keines der Tools das Festplattenproblem anzeigt.
Wenn wir uns
generic_make_request () ansehen , sehen wir, dass zwei Funktionen ausgeführt werden, bevor die Abrechnung beginnt. Das erste ist
generic_make_request_checks () , das leichtgewichtig ist und die Bio-
Daten gemäß den Geräteeinstellungen usw. überprüft. Der zweite ist
blk_queue_enter () , der einen
wait_event_interruptible () -Aufruf hat:
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));
Hier wartet der Kernel, bis die Warteschlange nicht mehr gefroren ist. Lassen Sie uns die Latenz von blk_queue_enter () messen:
~
Es sieht so aus, als wären wir nah dran. Die Funktionen zum Einfrieren / Auftauen der Warteschlange sind
blk_mq_freeze_queue und
blk_mq_unfreeze_queue . Sie werden verwendet, um die Einstellungen der Warteschlange zu ändern, was sich auf die derzeit im Flug befindlichen Io-Anforderungen auswirken kann. Wenn
blk_mq_freeze_queue () aufgerufen wird, wird
q-> mq_freeze_depth in
blk_freeze_queue_start () erhöht . Danach wartet der Kernel darauf, dass die Warteschlange in
blk_mq_freeze_queue_wait () leer ist.
Diese Wartezeit entspricht der Festplattenlatenz, da der Kernel warten muss, bis alle Io-Vorgänge abgeschlossen sind. Wenn die Warteschlange leer ist, können Änderungen vorgenommen werden. Der letzte Schritt besteht darin,
blk_mq_unfreeze_queue () aufzurufen , wodurch der Zähler
freeze_depth verringert wird.
Jetzt wissen wir genug, um das Problem zu beheben. Der Befehl udevadm trigger ändert die Einstellungen für Blockgeräte. Diese Einstellungen werden in den udev-Regeln beschrieben. Wir können herausfinden, welche Einstellungen die Warteschlange einfrieren, indem wir sie über sysfs ändern oder den Kernel-Quellcode betrachten. Alternativ können wir die
Ablaufverfolgung aus dem BCC-Toolkit
aufrufen , um Kernel- und Benutzerstapel für jeden Aufruf von
blk_freeze_queue zu drucken:
~
Udev-Regeln ändern sich nicht oft, sodass selbst das Zuweisen bereits vorhandener Werte zu bestimmten Parametern zu einem Anstieg der Übermittlungslatenz für die Anwendung führt. Das Generieren von udev-Ereignissen, wenn sich die Konfiguration eines Geräts nicht ändert (kein Gerät ist angeschlossen oder getrennt), ist natürlich keine gute Vorgehensweise. Trotzdem können wir verhindern, dass der Kernel die Warteschlange einfriert, wenn es keinen Grund dafür gibt.
Drei kleine Commits beheben das Problem.
Fazit
eBPF ist ein hochflexibles und leistungsstarkes Instrument. In diesem Artikel haben wir uns nur einen Fall angesehen und ein wenig gezeigt, wozu er in der Lage ist. Wenn Sie an der Entwicklung von BCC-basierten Tools interessiert sind, sollten Sie sich das
offizielle Tutorial ansehen, in dem die grundlegenden Konzepte beschrieben werden.
Es gibt auch andere interessante eBPF-basierte Tools zum Profilieren und Debuggen. Eines davon ist
bpftrace , mit dem Sie leistungsstarke Oneliner und kleine Programme in einer awk-ähnlichen Sprache schreiben können. Ein weiteres Beispiel ist
ebpf_exporter , mit dem Sie hochauflösende Metriken auf niedriger Ebene auf Ihrem Prometheus-Server mit hervorragenden Visualisierungs- und
Warnfunktionen erfassen können.