Linux verfügt über eine große Anzahl von Tools zum Debuggen des Kernels und der Anwendungen. Die meisten davon wirken sich negativ auf die Anwendungsleistung aus und können nicht in der Produktion verwendet werden.
Vor ein paar Jahren gab es das - eBPF. Es ermöglicht die Verfolgung des Kernels und der Benutzeranwendungen mit geringem Overhead und ohne die Notwendigkeit, Programme neu zu erstellen und Module von Drittanbietern in den Kernel zu laden.
Es gibt bereits viele Anwendungsdienstprogramme, die eBPF verwenden. In diesem Artikel sehen wir uns an, wie Sie Ihr eigenes Profilierungsdienstprogramm basierend auf der Bibliothek schreiben . Der Artikel basiert auf wahren Begebenheiten. Wir gehen vom Problem zur Lösung über und zeigen, wie vorhandene Dienstprogramme in bestimmten Situationen verwendet werden können.
Ceph ist langsam
Dem Ceph-Cluster wurde ein neuer Host hinzugefügt. Nachdem wir einige Daten dorthin migriert hatten, stellten wir fest, dass die Geschwindigkeit der Verarbeitung von Schreibanfragen durch ihn viel geringer war als auf anderen Servern.
Im Gegensatz zu anderen Plattformen verwendete dieser Host bcache und den neuen Linux 4.15-Kernel. Dies war das erste Mal, dass ein Host dieser Konfiguration hier verwendet wurde. Und in diesem Moment war klar, dass die Ursache des Problems theoretisch alles sein könnte.
Untersuchung des Hosts
Schauen wir uns zunächst an, was im ceph-osd-Prozess passiert. Dafür werden wir verwenden и (Mehr darüber können Sie lesen ):
Das Bild sagt uns, dass die Funktion fdatasync() Ich habe viel Zeit damit verbracht, eine Anfrage an Funktionen zu senden generic_make_request(). Dies bedeutet, dass die Ursache der Probleme höchstwahrscheinlich irgendwo außerhalb des OSD-Daemons selbst liegt. Dies kann entweder der Kernel oder Festplatten sein. Die iostat-Ausgabe zeigte eine hohe Latenz bei der Verarbeitung von Anforderungen durch 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. Das ist ein seltsames Verhalten, deshalb müssen Sie herausfinden, warum. Da Systemd-udevd mit uevents funktioniert, haben wir uns entschieden, sie durchzugehen udevadm Monitor. Es stellte sich heraus, dass für jedes Blockgerät im System eine große Anzahl von Änderungsereignissen generiert wurde. Das ist ziemlich ungewöhnlich, daher müssen wir uns ansehen, was all diese Ereignisse hervorruft.
Verwendung des BCC Toolkits
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. IN Es gibt bereits ein wunderbares Dienstprogramm - Funktionalität. Wir verfolgen den Daemon anhand seiner PID mit einem Intervall von 1 Sekunde zwischen den Ausgaben und geben das Ergebnis in Millisekunden aus.
Diese Funktion funktioniert normalerweise schnell. Es reicht lediglich aus, die Anforderung an die Gerätetreiberwarteschlange weiterzuleiten.
Cache ist ein komplexes Gerät, das eigentlich aus drei Festplatten besteht:
- Sicherungsgerät (zwischengespeicherte Festplatte), in diesem Fall eine langsame Festplatte;
- Caching-Gerät (Caching-Disk), hier ist dies eine Partition des NVMe-Geräts;
- das virtuelle bcache-Gerät, mit dem die Anwendung ausgeführt wird.
Wir wissen, dass die Übertragung von Anfragen langsam ist, aber für welches dieser Geräte? Wir werden uns etwas später damit befassen.
Wir wissen jetzt, dass UE-Ereignisse wahrscheinlich Probleme verursachen werden. Es ist nicht so einfach herauszufinden, was genau ihre Entstehung verursacht. Nehmen wir an, dass es sich um eine Art Software handelt, die regelmäßig gestartet wird. Sehen wir uns mithilfe eines Skripts an, welche Art von Software auf dem System ausgeführt wird execsnoop aus dem gleichen . Lassen Sie es uns ausführen und die Ausgabe in eine Datei senden.
Zum Beispiel so:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Wir werden hier nicht die vollständige Ausgabe von execsnoop zeigen, aber eine für uns interessante Zeile sah so 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 Threads unseres Überwachungssystems. Bei der Überprüfung der Konfiguration des Überwachungssystems wurden fehlerhafte Parameter gefunden. Die Temperatur des HBA-Adapters wurde alle 30 Sekunden gemessen, also viel häufiger als nötig. Nachdem wir das Prüfintervall auf ein längeres Intervall geändert hatten, stellten wir fest, dass die Latenz bei der Anforderungsverarbeitung auf diesem Host im Vergleich zu anderen Hosts nicht mehr auffiel.
Es ist jedoch immer noch unklar, warum das Bcache-Gerät so langsam war. Wir haben eine Testplattform mit einer identischen Konfiguration vorbereitet und versucht, das Problem zu reproduzieren, indem wir fio auf bcache ausgeführt haben und regelmäßig den udevadm-Trigger ausgeführt haben, um uevents zu generieren.
Schreiben von BCC-basierten Tools
Versuchen wir, ein einfaches Dienstprogramm zu schreiben, um die langsamsten Anrufe zu verfolgen und anzuzeigen generic_make_request(). Uns interessiert auch der Name des Laufwerks, für das diese Funktion aufgerufen wurde.
Der Plan ist einfach:
- Registrieren kprobe auf generic_make_request():
- Wir speichern den Festplattennamen im Speicher, auf den über das Funktionsargument zugegriffen werden kann.
- Wir speichern den Zeitstempel.
- Registrieren kretprobe für die Rückkehr von generic_make_request():
- Wir erhalten den aktuellen Zeitstempel;
- Wir suchen nach dem gespeicherten Zeitstempel und vergleichen ihn mit dem aktuellen;
- Wenn das Ergebnis größer als der angegebene Wert ist, suchen wir den Namen des gespeicherten Datenträgers und zeigen ihn auf dem Terminal an.
Kprobes и kretprobes Verwenden Sie einen Haltepunktmechanismus, um Funktionscode im laufenden Betrieb zu ändern. Du kannst lesen и Artikel zu diesem Thema. Wenn Sie sich den Code verschiedener Dienstprogramme ansehen in , dann können Sie sehen, dass sie eine identische Struktur haben. Daher überspringen wir in diesem Artikel das Parsen von Skriptargumenten und gehen zum BPF-Programm selbst über.
Der eBPF-Text im Python-Skript sieht folgendermaßen aus:
bpf_text = “”” # Here will be the bpf program code “””
Um Daten zwischen Funktionen auszutauschen, verwenden eBPF-Programme . Wir werden das Gleiche tun. Wir verwenden die Prozess-PID als Schlüssel und definieren die Struktur als Wert:
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 Schlüsseltyp u64 und ein Wert vom Typ struct data_t. Die Tabelle wird im Rahmen unseres BPF-Programms verfügbar sein. Das Makro BPF_PERF_OUTPUT registriert eine weitere aufgerufene Tabelle Veranstaltungen, das verwendet wird für in den Benutzerbereich.
Wenn Sie Verzögerungen zwischen dem Aufruf einer Funktion und der Rückkehr von ihr oder zwischen Aufrufen verschiedener Funktionen messen, müssen Sie berücksichtigen, dass die empfangenen Daten zum selben Kontext gehören müssen. Mit anderen Worten, Sie müssen an den möglichen parallelen Start von Funktionen denken. Wir haben die Möglichkeit, die Latenz zwischen dem Aufruf einer Funktion im Kontext eines Prozesses und der Rückkehr von dieser Funktion im Kontext eines anderen Prozesses zu messen, aber das ist wahrscheinlich nutzlos. Ein gutes Beispiel wäre hier , wobei der Hash-Tabellenschlüssel auf einen Zeiger auf gesetzt ist Strukturanfrage, was eine Festplattenanforderung widerspiegelt.
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 erste Argument der aufgerufenen Funktion als zweites Argument ersetzt . Danach erhalten wir die PID des Prozesses, in dem wir arbeiten, und den aktuellen Zeitstempel in Nanosekunden. Wir schreiben alles in einer frisch ausgewählten Form auf struct data_t Daten. Den Datenträgernamen erhalten wir aus der Struktur Bio, die beim Aufruf übergeben wird generic_make_request(), und speichern Sie es in derselben Struktur technische Daten. Der letzte Schritt besteht darin, einen Eintrag zur zuvor erwähnten Hash-Tabelle hinzuzufügen.
Die folgende Funktion wird bei der Rückkehr von aufgerufen 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);
}
}
Diese Funktion ähnelt der vorherigen: Wir ermitteln die PID des Prozesses und den Zeitstempel, weisen jedoch keinen Speicher für die neue Datenstruktur zu. Stattdessen durchsuchen wir die Hash-Tabelle nach einer bereits 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. diese. PID des Hauptprozesses, der den Thread gestartet hat, in dessen Kontext wir arbeiten. Die Funktion, die wir aufrufen gibt sowohl die GID als auch die PID des Threads in einem einzigen 64-Bit-Wert zurück.
Bei der Ausgabe an das Terminal interessiert uns derzeit nicht der Thread, sondern der Hauptprozess. Nachdem wir die resultierende Verzögerung mit einem bestimmten Schwellenwert verglichen haben, übergeben wir unsere Struktur technische Daten in den Benutzerbereich über die Tabelle Veranstaltungen, danach löschen wir den Eintrag aus p.
Im Python-Skript, das diesen Code lädt, müssen wir MIN_US und FACTOR durch die Verzögerungsschwellenwerte und Zeiteinheiten ersetzen, die wir über die Argumente übergeben:
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 vorbereiten und Proben 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 feststellen struct data_t in unserem Skript, sonst können wir nichts lesen:
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)]
Der letzte Schritt besteht darin, Daten an das Terminal auszugeben:
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()
Das Skript selbst ist verfügbar unter . Versuchen wir es auf einer Testplattform auszuführen, auf der fio läuft, in den Bcache schreibt und udevadm monitor aufruft:
Endlich! Jetzt sehen wir, dass das, was wie ein blockierendes Bcache-Gerät aussah, in Wirklichkeit ein Verzögerungsanruf ist generic_make_request() für eine zwischengespeicherte Festplatte.
Tauchen Sie ein in den Kernel
Was genau führt zu einer Verlangsamung bei der Anforderungsübertragung? Wir sehen, dass die Verzögerung bereits vor Beginn der Anforderungsabrechnung auftritt, d. h. Die Abrechnung einer bestimmten Anfrage zur weiteren Ausgabe von Statistiken dazu (/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 , die auf dem Beginn und Ende der Anforderungsabrechnung basiert. Keines dieser Dienstprogramme zeigt Probleme bei Anfragen an die zwischengespeicherte Festplatte.
Wenn wir uns die Funktion ansehen generic_make_request(), dann werden wir sehen, dass vor Beginn der Anforderungsabrechnung zwei weitere Funktionen aufgerufen werden. Erste - generic_make_request_checks(), führt Überprüfungen der Legitimität der Anfrage hinsichtlich der Festplatteneinstellungen durch. Zweite - , was eine interessante Herausforderung mit sich bringt :
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 darauf, dass die Warteschlange freigegeben wird. Lassen Sie uns die Verzögerung messen 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 | |
Es sieht so aus, als wären wir einer Lösung nahe. Die zum Einfrieren/Entfrieren einer Warteschlange verwendeten Funktionen sind: и . Sie werden verwendet, wenn es notwendig ist, die Einstellungen der Anforderungswarteschlange zu ändern, was für Anforderungen in dieser Warteschlange möglicherweise gefährlich ist. Beim Anrufen blk_mq_freeze_queue() функцией Der Zähler wird erhöht q->mq_freeze_ Depth. Danach wartet der Kernel darauf, dass die Warteschlange leer wird .
Die zum Löschen dieser Warteschlange benötigte Zeit entspricht der Festplattenlatenz, da der Kernel darauf wartet, dass alle Vorgänge in der Warteschlange abgeschlossen sind. Sobald die Warteschlange leer ist, werden die Einstellungsänderungen übernommen. Danach heißt es , Dekrementieren des Zählers Freeze_Tiefe.
Jetzt wissen wir genug, um die Situation zu korrigieren. Der Triggerbefehl udevadm bewirkt, dass die Einstellungen für das Blockgerät angewendet werden. Diese Einstellungen werden in den udev-Regeln beschrieben. Wir können 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-Dienstprogramm ausprobieren , das für jeden Aufruf des Terminals Kernel- und Userspace-Stack-Traces ausgibt blk_freeze_queuezum Beispiel:
~# /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]
Die Udev-Regeln ändern sich recht selten und normalerweise geschieht dies auf kontrollierte Weise. Wir sehen also, dass selbst die Anwendung der bereits festgelegten Werte zu einem Anstieg der Verzögerung bei der Übertragung der Anfrage von der Anwendung auf die Festplatte führt. Natürlich ist es keine gute Praxis, udev-Ereignisse zu generieren, wenn sich keine Änderungen an der Festplattenkonfiguration ergeben (z. B. wenn das Gerät nicht gemountet/getrennt ist). Wir können jedoch dazu beitragen, dass der Kernel keine unnötige Arbeit verrichtet und die Anforderungswarteschlange einfriert, wenn dies nicht erforderlich ist. die Situation korrigieren.
Zusammenfassung
eBPF ist ein sehr flexibles und leistungsstarkes Tool. In dem Artikel haben wir uns einen praktischen Fall angesehen und einen kleinen Teil dessen gezeigt, was getan werden kann. Wenn Sie an der Entwicklung von BCC-Dienstprogrammen interessiert sind, lohnt es sich, einen Blick darauf zu werfen , das die Grundlagen gut beschreibt.
Es gibt weitere interessante Debugging- und Profiling-Tools, die auf eBPF basieren. Einer von ihnen - , mit dem Sie leistungsstarke Einzeiler und kleine Programme in der awk-ähnlichen Sprache schreiben können. Ein anderer - ermöglicht es Ihnen, Low-Level-Metriken mit hoher Auflösung direkt auf Ihrem Prometheus-Server zu sammeln und später schöne Visualisierungen und sogar Warnungen zu erhalten.
Source: habr.com