bpftrace misst die Dauer von read()-Systemaufrufen zwischen den zugehörigen Entry- und Exit-Tracepoints. Das Skript verbindet beide Ereignisse über die Thread-ID; im Histogramm erscheinen nur vollständig erfasste Aufrufe. Die Messung umfasst auch Wartezeiten außerhalb der CPU und entspricht deshalb keiner reinen Geräte-Latenz.
Für die erste Diagnose ziehe ich ein prozessbezogenes Latenzhistogramm einem systemweiten Syscall-Mitschnitt vor, weil sich der lange Latenzausläufer damit einer abgegrenzten Arbeitslast zuordnen lässt.
Welche Linux-Syscall-Latenz soll die Messung erklären?
Als Referenz dient dieselbe Arbeitslast ohne das beobachtete Verzögerungssymptom. Ein Aufruf ist nicht allein deshalb problematisch, weil er länger dauert als die übrigen: Entscheidend sind die Anforderungen der Anwendung und die Abweichung von der Referenzmessung. Das Skript erfasst zunächst ausschließlich read(); für write() lässt sich das Messmuster später übertragen.
Zum Messprotokoll gehören die Eingabedaten, die Anzahl paralleler Threads und der Zeitraum der beobachteten Verzögerung. Ein Programmstart mit kaltem Page-Cache ist nicht unmittelbar mit einer Wiederholung vergleichbar, bei der die Daten bereits im RAM liegen. Für spätere Vergleiche werden auch die Kernel- und bpftrace-Version festgehalten.
Welche Tracepoints und Berechtigungen sind verfügbar?
Mit -l listet bpftrace die verfügbaren Probes auf; -lv zeigt zusätzlich die Argumentfelder eines Tracepoints. Die folgenden Befehle erfassen außerdem die Distribution, die Kernel-Version und die Prozessorarchitektur.
bpftrace --version
uname -r
uname -m
cat /etc/os-release
sudo bpftrace -l 'tracepoint:syscalls:sys_*_read'
sudo bpftrace -l 'tracepoint:syscalls:sys_*_write'
sudo bpftrace -lv 'tracepoint:syscalls:sys_enter_read'
sudo bpftrace -lv 'tracepoint:syscalls:sys_exit_read'Die Beispiele verwenden sudo. Kernel-Lockdown, fehlende Capabilities oder die Sicherheitsregeln eines Containers können das Laden der BPF-Programme trotzdem verhindern. Für einen ersten Versuch eignet sich deshalb eine Testumgebung mit reproduzierbarer Last.
Sind beide read()-Tracepoints verfügbar, verbindet das Skript Eintritt und Rückkehr über die Thread-ID.
Warum braucht jeder Thread einen eigenen Startzeitstempel?
Mehrere Threads eines Prozesses können gleichzeitig in read() warten. Ein gemeinsamer Startzeitstempel unter der Prozess-ID würde deshalb bei einem weiteren Eintritt überschrieben. Im Skript dient tid als Schlüssel; der Filter mit pid erfasst die gesamte Thread-Gruppe des ausgewählten Prozesses.
Die Datei read-latency.bt enthält folgendes Skript und erwartet die Ziel-PID als erstes Argument:
tracepoint:syscalls:sys_enter_read
/pid == $1/
{
@start[tid] = nsecs;
}
tracepoint:syscalls:sys_exit_read
/pid == $1 && @start[tid]/
{
$elapsed_ns = nsecs - @start[tid];
@read_us = hist($elapsed_ns / 1000);
@calls = count();
delete(@start[tid]);
}
interval:s:30
{
exit();
}
END
{
clear(@start);
}Der Aufruf lautet beispielsweise sudo bpftrace read-latency.bt 1234, wobei 1234 für die Ziel-PID steht. Nach etwa 30 Sekunden beendet bpftrace die Messung und gibt die Aggregations-Maps aus. Die Hilfsmap @start wird im END-Block geleert, damit keine verbliebenen Startzeitstempel erscheinen.
Der Exit-Filter verarbeitet nur Rückgaben mit einem zuvor erfassten Entry; anschließend entfernt delete() den Startzeitstempel des Threads. Die Differenz der beiden nsecs-Werte liegt zunächst in Nanosekunden vor. Erst die Division durch 1000 rechnet sie für das Histogramm in Mikrosekunden um.
Wie lassen sich bpftrace-Latenzhistogramme lesen?
Der Map-Name @read_us kennzeichnet die Einheit Mikrosekunden. Bei der ganzzahligen Division werden Nachkommastellen abgeschnitten; Dauern unter einer Mikrosekunde erscheinen daher als null. Die Umrechnung erfolgt vor der Aggregation, nicht erst beim Drucken der Map.
Standardmäßig gruppiert hist() die Werte logarithmisch. Ein Bucket [8, 16) enthält beispielsweise Aufrufe ab 8 bis unter 16 Mikrosekunden, während [1024, 2048) ungefähr eine bis zwei Millisekunden abdeckt. Wenige Aufrufe in weit rechts liegenden Buckets bilden einen langen Latenzausläufer, auch wenn die meisten Aufrufe in den linken Buckets liegen.
Mehr Buckets oder feste Zeitbereiche
Mit hist($elapsed_ns / 1000, 2) entstehen vier Buckets pro Zweierpotenzintervall. Der Granularitätsparameter reicht von 0 bis 5 und entspricht damit 1 bis 32 Buckets je Intervall.
Für feste Zeitbereiche eignet sich beispielsweise lhist($elapsed_ns / 1000, 0, 10000, 500). Zwischen 0 und unter 10.000 Mikrosekunden entstehen gleich breite 500-Mikrosekunden-Buckets; Werte ab 10.000 Mikrosekunden erscheinen im oberen Rand-Bucket. Ein zusätzlicher unterer Rand-Bucket erfasst Werte unter null, die bei dieser Zeitdifferenz nicht zu erwarten sind.
Bei einer Erweiterung um write() bleiben Startzeitstempel und Histogramme getrennt, etwa als @read_start, @write_start, @read_us und @write_us. Für den Vergleich der Histogramme bleiben Messfenster und Arbeitslast gleich.
Welche Aufrufe zählt die Messung?
@calls enthält nur Aufrufe, deren Entry und Exit während der Messung erfasst wurden. Ein vor dem Start begonnener Aufruf fehlt ebenso wie ein Aufruf, der beim Messende noch läuft. Rückgaben ohne gelesene Bytes und negative Rückgabewerte fließen ebenfalls ein, weil das Skript args->ret am Exit-Tracepoint nicht filtert.
Für Vergleichsläufe bleiben die 30 Sekunden, die Eingabedaten und die Parallelität unverändert; der Cache-Zustand wird ebenfalls protokolliert. Mehrere Wiederholungen zeigen, ob ein verschobener Latenzausläufer erneut auftritt. Aus einzelnen langsamen Aufrufen bei geringer Aufrufzahl lassen sich weder eine prozentuale Leistungsänderung noch eine Ursache ableiten.
Der PID-Filter verwirft Ereignisse fremder Prozesse erst im BPF-Programm; die Syscall-Tracepoints werden weiterhin systemweit ausgelöst. Ein zusätzlicher Testlauf ohne Tracing zeigt, ob sich die Laufzeit der Anwendung durch den Messeingriff verändert. Tritt der Latenzausläufer wiederholt auf, folgt die Untersuchung der Wartezeit des Threads.
Welche Ursachen kommen für lange Aufrufe infrage?
Während eines Aufrufs führt der Kernel Code aus; ein blockierter Thread wartet beispielsweise auf Daten von einer Pipe oder einem Socket. Nach dem Aufwecken kann weitere Zeit vergehen, bis der Scheduler dem Thread wieder eine CPU zuteilt. Bei Schreibzugriffen kommt eine andere Grenze hinzu: Gepufferte write()-Aufrufe können zurückkehren, bevor die Daten den Datenträger erreichen.
Der Dateideskriptor steht beim Entry in args->fd; unter /proc/PID/fd/N lässt sich sein aktuelles Ziel untersuchen. Diese Zuordnung gilt für den Abfragezeitpunkt, denn ein Prozess kann einen Deskriptor schließen und dieselbe Nummer später für ein anderes Ziel verwenden. Je nach Ziel und Begleitsymptom liefern folgende Werkzeuge weitere Messwerte:
pidstat -u -w -p 1234 1zeigt CPU-Nutzung und Kontextwechsel des Prozesses; mitperf schedlassen sich anschließend Scheduler-Verzögerungen untersuchenvmstat 1zeigt unter anderem Swap-Aktivität; unter/proc/pressure/memorymeldet der Kernel bei aktivierter PSI-Unterstützung Wartezeiten durch Speicherdruckiostat -xz 1liefert Gerätekennzahlen für eine anschließende I/O-Untersuchung, misst aber nicht denselben Vorgang wie das Syscall-Histogrammss -tinpzeigt TCP-Verbindungen mit Prozesszuordnung und Informationen wie RTT oder Retransmissionszählern, sofern die Berechtigungen dafür ausreichen
Bleibt @calls trotz erwarteter Lesezugriffe leer, stehen vor der Ursachenanalyse zunächst der Prozessfilter und die verwendeten Systemaufrufe zur Untersuchung an.
Warum bleiben Probes oder Messwerte aus?
Fehlen bereits die gesuchten Tracepoints in der Probe-Liste, hängt das Problem mit der lokalen Kernel- und Tracing-Umgebung zusammen. Bei vorhandenen Probes ohne Beobachtungen kommen eine falsche PID, ein anderer PID-Namespace oder andere Systemaufrufe infrage. Anwendungen können beispielsweise pread64(), readv() oder io_uring statt read() verwenden.
Mit sudo bpftrace -v read-latency.bt 1234 erscheinen zusätzliche Lade- und Verifier-Diagnosen. Der BPF-Verifier prüft unter anderem Speicherzugriffe und zulässige Helper-Aufrufe. Eine verweigerte Berechtigung oder ein fehlender Tracepoint ist jedoch nicht mit einer Ablehnung des Programms durch den Verifier gleichzusetzen.
Für eine maschinenlesbare Ausgabe aktiviert -f json das JSON-Format. Die folgende Umleitung trennt die ausgegebenen JSON-Datensätze von Diagnosemeldungen auf der Standardfehlerausgabe:
sudo bpftrace -f json read-latency.bt 1234 >messung.jsonl 2>diagnose.logNach erfolgreichem Laden lassen sich die Arbeit mit eBPF und die weiterführende Linux-Fehlersuche getrennt vertiefen.
Nächster Diagnoseschritt: einen Dateideskriptor isolieren
Für einen einzelnen Dateideskriptor wird nur der Entry-Filter erweitert; am Exit-Tracepoint steht kein fd-Argument bereit. Grenze als nächsten Schritt die Messung auf den zuvor zugeordneten Deskriptor ein, indem du im Skript den Entry-Filter durch diese Zeile ersetzt:
/pid == $1 && args->fd == $2/Mit sudo bpftrace read-latency.bt 1234 7 erfasst das Histogramm anschließend nur die Aufrufe des Prozesses 1234, die beim Eintritt den Deskriptor 7 verwenden. Der Exit-Filter bleibt unverändert, weil die Zuordnung weiterhin über den gespeicherten Startzeitstempel des Threads erfolgt.