Linux verfügt über eine große Anzahl von Kernel-Debugging-Tools und -Anwendungen. Die meisten von ihnen beeinträchtigen die Anwendungsleistung und können nicht in der Produktion verwendet werden.
Vor einigen Jahren wurde ein
weiteres Tool entwickelt - eBPF. Es ermöglicht die Verfolgung des Kernels und der Benutzeranwendungen mit geringem Overhead und ohne dass Programme neu erstellt und Module von Drittanbietern in den Kernel geladen werden müssen.
Jetzt gibt es viele Anwendungsdienstprogramme, die eBPF verwenden. In diesem Artikel erfahren Sie, wie Sie unser eigenes Profiling-Dienstprogramm basierend auf der
PythonBCC- Bibliothek schreiben. Der Artikel basiert auf realen Ereignissen. Wir werden vom Auftreten des Problems bis zu seiner Korrektur gehen, um zu zeigen, wie vorhandene Dienstprogramme in bestimmten Situationen verwendet werden können.
Ceph ist langsam
Dem Ceph-Cluster wurde ein neuer Host hinzugefügt. Nach der Migration einiger Daten haben wir festgestellt, dass die Geschwindigkeit der Verarbeitung von Schreibanforderungen viel geringer ist als auf anderen Servern.
Im Gegensatz zu anderen Plattformen wurden auf diesem Host bcache und der neue Linux 4.15-Kernel verwendet. Hier wurde erstmals ein Host dieser Konfiguration verwendet. Und zu dieser Zeit war klar, dass theoretisch alles die Wurzel des Problems sein könnte.
Untersuchung des Gastgebers
Lassen Sie uns zunächst sehen, was im ceph-osd-Prozess passiert. Dazu verwenden wir
Perf und
Flamescope (mehr dazu
hier ):
Das Bild zeigt, dass die Funktion
fdatasync () viel Zeit damit verbracht hat, eine Anforderung an die Funktion
generic_make_request () zu
senden . Dies bedeutet, dass die Ursache der Probleme höchstwahrscheinlich irgendwo außerhalb des osd-Daemons selbst liegt. Es kann sich entweder um einen Kernel oder um Festplatten handeln. Die iostat-Ausgabe zeigte eine hohe Latenz bei der Verarbeitung von Anforderungen mit bcache-Festplatten.
Bei der Überprüfung des Hosts haben wir festgestellt, dass der systemd-udevd-Daemon viel CPU-Zeit verbraucht - etwa 20% auf mehreren Kernen. Dies ist ein seltsames Verhalten, daher müssen Sie die Ursache herausfinden. Da Systemd-udevd mit uevents arbeitet, haben wir uns entschlossen, sie über den
udevadm-Monitor zu betrachten . Es stellt sich heraus, dass für jedes Blockgerät im System eine große Anzahl von Änderungsereignissen generiert wurde. Dies ist ziemlich ungewöhnlich, daher müssen Sie sehen, was all diese Ereignisse erzeugt.
Verwenden des BCC Toolkit
Wie wir bereits herausgefunden haben, verbringt der Kernel (und der Ceph-Daemon im Systemaufruf) viel Zeit in
generic_make_request () . Versuchen wir, die Geschwindigkeit dieser Funktion zu messen.
BCC hat bereits ein großartiges Dienstprogramm - die
Funclatency . Wir werden den Dämon anhand seiner PID mit einem Intervall zwischen den Informationsausgaben von 1 Sekunde verfolgen und das Ergebnis in Millisekunden ausgeben.
Normalerweise ist diese Funktion schnell. Sie sendet die Anforderung lediglich an die Gerätetreiberwarteschlange.
Bcache ist ein komplexes Gerät, das tatsächlich aus drei Festplatten besteht:
- Sicherungsgerät (zwischengespeicherte Festplatte), in diesem Fall eine langsame Festplatte;
- Caching-Gerät (Caching-Datenträger), hier ist es ein Abschnitt des NVMe-Geräts;
- bcache virtuelles Gerät, mit dem die Anwendung arbeitet.
Wir wissen, dass die Anforderungsübertragung langsam ist, aber für welches dieser Geräte? Wir werden uns etwas später darum kümmern.
Wir wissen jetzt, dass Ereignisse wahrscheinlich Probleme verursachen. Es ist nicht so einfach herauszufinden, was genau ihre Entstehung verursacht. Angenommen, dies ist eine Art Software, die regelmäßig ausgeführt wird. Lassen Sie uns sehen, welche
Art von Software auf dem System mithilfe des
execsnoop- Skripts aus denselben
BCC-Dienstprogrammen gestartet wird. Führen Sie es aus und leiten Sie die Ausgabe in eine Datei.
Zum Beispiel so:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Wir werden hier nicht die vollständige Ausgabe von execsnoop geben, aber eine für uns interessante Zeile sah folgendermaßen aus:
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 (übergeordnete PID) des Prozesses. Der Prozess mit PID 5802 erwies sich als einer der Fäden unseres Überwachungssystems. Bei der Überprüfung der Konfiguration des Überwachungssystems wurden fehlerhafte Parameter gefunden. Die Temperatur des HBA-Adapters wurde alle 30 Sekunden gemessen, was viel häufiger als nötig ist. Nachdem wir das Überprüfungsintervall in ein längeres geändert haben, haben wir festgestellt, dass sich die Verzögerung bei der Verarbeitung von Anforderungen auf diesem Host nicht mehr von den übrigen Hosts abhebt.
Es ist jedoch immer noch nicht klar, warum das bcache-Gerät so langsam war. Wir haben eine Testplattform mit identischer Konfiguration vorbereitet und versucht, das Problem zu reproduzieren, indem wir fio auf bcache ausgeführt haben und regelmäßig den udevadm-Trigger gestartet haben, um Ereignisse zu generieren.
Schreiben von BCC-basierten Tools
Versuchen wir, ein einfaches Dienstprogramm zum Verfolgen und Anzeigen der langsamsten Aufrufe von
generic_make_request () zu
schreiben . Uns interessiert auch der Name des Laufwerks, für das diese Funktion aufgerufen wurde.
Der Plan ist einfach:
- Registrieren Sie kprobe bei generic_make_request () :
- Wir speichern den Datenträgernamen, auf den über das Funktionsargument zugegriffen werden kann.
- Speichern Sie den Zeitstempel.
- Registrieren Sie kretprobe , um von generic_make_request () zurückzukehren :
- Holen Sie sich den aktuellen Zeitstempel.
- Wir suchen nach dem gespeicherten Zeitstempel und vergleichen ihn mit dem aktuellen.
- Wenn das Ergebnis größer als das angegebene ist, suchen wir den gespeicherten Datenträgernamen und zeigen ihn auf dem Terminal an.
Kprobes und
Kretprobes verwenden einen Haltepunktmechanismus, um den Funktionscode im
laufenden Betrieb zu ändern. Sie können die
Dokumentation und einen
guten Artikel zu diesem Thema lesen. Wenn Sie sich den Code verschiedener Dienstprogramme in
BCC ansehen, werden Sie feststellen, dass sie eine identische Struktur haben. In diesem Artikel werden wir also das Parsen von Skriptargumenten weglassen und zum BPF-Programm selbst übergehen.
Der eBPF-Text im Python-Skript sieht folgendermaßen aus:
bpf_text = “””
Zum Austausch von Daten zwischen Funktionen verwenden eBPF-Programme
Hash-Tabellen . Wir werden es auch tun. Als Schlüssel verwenden wir die PID des Prozesses und als Wert definieren wir die Struktur:
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 Hash-Tabelle namens
p mit einem Schlüssel vom Typ
u64 und einem Wert vom Typ
struct data_t . Die Tabelle wird im Rahmen unseres BPF-Programms verfügbar sein. Das Makro BPF_PERF_OUTPUT registriert eine andere Tabelle namens
Ereignisse , mit der
Daten in den Benutzerbereich übertragen werden.
Bei der Messung von Verzögerungen zwischen einem Funktionsaufruf und dessen Rückgabe oder zwischen Aufrufen verschiedener Funktionen sollte berücksichtigt werden, dass die empfangenen Daten zum selben Kontext gehören müssen. Mit anderen Worten, Sie müssen sich an den möglichen parallelen Start von Funktionen erinnern. Wir haben die Möglichkeit, die Verzögerung zwischen dem Aufrufen einer Funktion im Kontext eines Prozesses und der Rückkehr von dieser Funktion im Kontext eines anderen Prozesses zu messen, aber dies ist höchstwahrscheinlich nutzlos. Ein gutes Beispiel hierfür ist das
Biolatency-Dienstprogramm , bei dem ein Zeiger auf eine
Strukturanforderung , die eine einzelne Festplattenanforderung widerspiegelt, als Schlüssel in der Hash-Tabelle festgelegt wird.
Als nächstes müssen wir den Code schreiben, der ausgeführt wird, wenn die untersuchte Funktion aufgerufen 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 wird das zweite Argument der aufgerufenen Funktion
generic_make_request () als zweites Argument ersetzt. Danach erhalten wir die PID des Prozesses, in dem wir arbeiten, und den aktuellen Zeitstempel in Nanosekunden. All dies schreiben wir in die
neu zugewiesenen struct data_t data . Wir erhalten den Datenträgernamen aus der
Biostruktur , die beim Aufruf von
generic_make_request () übergeben wird , und speichern ihn in derselben
Datenstruktur . Der letzte Schritt besteht darin, der zuvor erwähnten Hash-Tabelle einen Eintrag hinzuzufügen.
Die folgende Funktion wird bei der Rückkehr von
generic_make_request () aufgerufen :
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); } }
Diese Funktion ähnelt der vorherigen: Wir erkennen die Prozess-PID und den Zeitstempel, weisen jedoch keinen Speicher für die neue Datenstruktur zu. Stattdessen suchen wir in der Hash-Tabelle nach einer vorhandenen Struktur mit dem Schlüssel == aktuelle PID. Wenn die Struktur gefunden wird, ermitteln wir den Namen des laufenden Prozesses und fügen ihn hinzu.
Die hier verwendete binäre Verschiebung wird benötigt, um die Thread-GID zu erhalten. d.h. Die PID des Hauptprozesses, der den Thread gestartet hat, in dessen Kontext wir arbeiten. Die von uns
aufgerufene Funktion
bpf_get_current_pid_tgid () gibt sowohl die GID des Threads als auch seine PID in einem 64-Bit-Wert zurück.
Bei der Ausgabe an das Terminal interessieren wir uns jetzt nicht mehr für den Stream, sondern für den Hauptprozess. Nachdem wir die empfangene Verzögerung mit einem bestimmten Schwellenwert verglichen haben, übertragen wir unsere
Datenstruktur über die
Ereignistabelle in den Benutzerbereich und löschen dann den Datensatz aus
p .
In dem Python-Skript, das diesen Code lädt, müssen wir MIN_US und FACTOR durch die Verzögerungsschwellen und Zeiteinheiten ersetzen, die wir durch die Argumente weitergeben:
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"
Jetzt müssen wir das BPF-Programm über das
BPF-Makro vorbereiten und die Beispiele 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
struct data_t in unserem Skript definieren, sonst können wir nichts lesen:
TASK_COMM_LEN = 16
Der letzte Schritt ist die Datenausgabe an das Terminal:
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 Skript selbst ist auf
GItHub verfügbar. Versuchen wir es auf einer Testplattform auszuführen, auf der fio in bcache geschrieben ist, und rufen Sie udevadm monitor auf:
Endlich! Jetzt sehen wir, dass das, was wie ein bremsendes Bcache-Gerät aussah, tatsächlich ein
Bremsaufruf von
generic_make_request () auf einem zwischengespeicherten Laufwerk ist.
Grabe dich in den Kernel
Was genau verlangsamt sich während der Übertragung der Anfrage? Wir sehen, dass die Verzögerung bereits vor dem Beginn der Abrechnung der Anforderung auftritt, d. H. Die Berücksichtigung einer bestimmten Anforderung weiterer Statistiken (/ proc / diskstats oder iostat) hat noch nicht begonnen. Dies kann leicht überprüft werden, indem iostat ausgeführt wird, während das Problem reproduziert wird, oder das
BCC-Biolatency-Skript , das auf dem Beginn und dem Ende der Abrechnung von Anforderungen basiert. Keines dieser Dienstprogramme zeigt Probleme bei Abfragen an das zwischengespeicherte Laufwerk.
Wenn wir uns die Funktion
generic_make_request () ansehen , werden wir sehen, dass zwei weitere Funktionen aufgerufen werden, bevor die Anforderung
aufgezeichnet wird . Der erste,
generic_make_request_checks () , überprüft die Legitimität einer Anforderung für Festplatteneinstellungen. Das zweite ist
blk_queue_enter () , das einen interessanten Aufruf von
wait_event_interruptible () 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));
Darin wartet der Kernel auf das Auftauen der Warteschlange. Wir messen die Verzögerung
blk_queue_enter () :
~
Es scheint, dass wir einer Lösung nahe sind. Die Funktionen zum "Einfrieren / Auftauen" der Warteschlange sind
blk_mq_freeze_queue und
blk_mq_unfreeze_queue . Sie werden verwendet, wenn die Einstellungen der Abfragewarteschlange geändert werden müssen, die für die Abfragen in dieser Warteschlange möglicherweise gefährlich sind. Wenn
blk_mq_freeze_queue () aufgerufen wird, erhöht die Funktion
blk_freeze_queue_start () den
Zähler q-> mq_freeze_depth . Danach wartet der Kernel auf das Leeren der Warteschlange in
blk_mq_freeze_queue_wait () .
Die Wartezeit zum Löschen dieser Warteschlange entspricht der Festplattenlatenz, da der Kernel darauf wartet, dass alle Operationen in der Warteschlange abgeschlossen sind. Sobald die Warteschlange leer ist, werden Änderungen an den Einstellungen angewendet. Dann wird
blk_mq_unfreeze_queue () aufgerufen,
wodurch der Zähler
freeze_depth dekrementiert
wird .
Jetzt wissen wir genug, um die Situation zu korrigieren. Der Befehl udevadm trigger führt zur Anwendung von Einstellungen für das Blockgerät. Diese Einstellungen sind in den udev-Regeln beschrieben. Wir können genau herausfinden, welche Einstellungen die Warteschlange "einfrieren", indem wir versuchen, sie über sysfs zu ändern, oder indem wir uns den Kernel-Quellcode ansehen. Wir können auch das BCC-
Trace- Dienstprogramm ausprobieren, das den Kernel-Stack und die User-Space-Traces für das Terminal für jeden Aufruf von
blk_freeze_queue anzeigt , zum Beispiel:
~
Udev-Regeln ändern sich ziemlich selten und normalerweise geschieht dies unter Kontrolle. Wir sehen also, dass selbst die Verwendung bereits festgelegter Werte die Verzögerung bei der Übertragung der Anforderung von der Anwendung auf die Festplatte erhöht. Das Generieren von udev-Ereignissen, wenn keine Änderungen an der Festplattenkonfiguration vorgenommen wurden (z. B. wenn das Gerät keine Verbindung herstellt / trennt), ist natürlich keine gute Vorgehensweise. Wir können dem Kernel jedoch helfen, keine nutzlose Arbeit zu leisten und die Anforderungswarteschlange nicht einzufrieren, wenn dies nicht erforderlich ist.
Drei kleine Commits korrigieren die Situation.
Fazit
eBPF ist ein sehr flexibles und leistungsstarkes Tool. In dem Artikel haben wir einen praktischen Fall untersucht und einen kleinen Teil dessen gezeigt, was möglich ist. Wenn Sie an der Entwicklung von BCC-Dienstprogrammen interessiert sind, sollten Sie sich das
offizielle Tutorial ansehen, in dem die Grundlagen gut beschrieben werden.
Es gibt andere interessante Debugging- und Profiling-Tools, die auf eBPF basieren. Eines davon ist
bpftrace , mit dem Sie leistungsstarke einzeilige und kleine Programme in einer awk-ähnlichen Sprache schreiben können. Ein anderer -
ebpf_exporter - ermöglicht es Ihnen, hochauflösende Metriken auf niedriger Ebene direkt auf Ihrem Prometheus-Server zu sammeln und in Zukunft eine schöne Visualisierung und sogar Warnungen zu erhalten.