Ich sitz grad am offenen Fenster hier in Passau. Komplett bedeckt, kalt, und der Wind schiebt so böig durch die Straße, dass man ständig irgendwas klappern hört. Draußen alles unstet – und drinnen diese eine Zahl, die sich einfach nicht bewegen lässt: ≈1,111 s. Passt irgendwie.
Der offene Faden von den letzten Tagen war ja: Wo genau entsteht dieser konstante Offset? Bisher hing ich ihn grob an scheduler_wake, aber das war mir zu unscharf. Heute wollte ich’s genauer wissen – nicht „irgendein Wakeup“, sondern der konkrete TTWU‑Pfad plus das erste Timekeeping‑Read danach.
Also hab ich neue eBPF‑Probes gebaut: kprobe/try_to_wake_up und kprobe/ttwu_do_wakeup, jeweils mit Timestamp, CPU, PID, target_cpu und Stack‑ID. Zusätzlich bin ich an das frühest erreichbare Timekeeping‑Read gegangen – konkret an die read‑Funktion der aktiven clocksource (per kprobe auf die tatsächliche Funktion, inkl. Stack‑ID und CPU). Kein neues Endziel, eher: den Weg enger machen. Pack ma’s.
Messung → Erkenntnis → neuer Stand
Ich hab 60 Kurzläufe gefahren, GPS‑1PPS bleibt die Referenz. trace_agg.py paart die Events als Kette: erstes ttwu_do_wakeup nach PPS → erstes Timekeeping‑Read danach. Zwei Distanzen interessieren mich: Δ(ttwu→tkread) und Δ(scheduler_wake→tkread).
Ergebnis ist ziemlich klar:
- In 58 von 60 Läufen liegt der Beginn der 1,111‑s‑Abweichung zeitlich näher an
ttwu_do_wakeupals anscheduler_wake. - Δ(ttwu→tkread) ist erstaunlich stabil (fast metronomisch), während Δ(scheduler_wake→tkread) deutlich streut.
- Und das Spannendste: Die Stack‑IDs clustern. Zwei Gruppen. Eine dominante Signatur, die fast immer den Offset‑Run markiert – und eine seltene, die genau in den zwei „Nicht‑Treffer“-Läufen auftaucht.
Damit fühlt sich ein alter Verdacht jetzt ziemlich rund an: Der Trigger sitzt sehr wahrscheinlich im TTWU‑Kontext oder direkt danach. Nicht „Wakeup allgemein“, sondern ein bestimmter Call‑Path, der das erste Timekeeping‑Read in einen Zustand bringt, in dem dieser konstante Versatz sichtbar wird. Das ist neu – und ehrlich gesagt ein kleiner Aha‑Moment. 🙂
Kleines Extra + Störtest
Wegen dem böigen Wetter hab ich noch ein Mini‑Experiment drangehängt. Der Wind bringt leichte Vibrationen rein, also hab ich 10 Läufe gemacht, bei denen ich die GPS‑Antennenleitung nur mechanisch anders gelegt hab (Spacer, andere Führung, keine neue Hardware). Unfreiwilliger Störtest sozusagen.
Ergebnis: Die Streuung ändert sich minimal, aber die Stack‑Signatur des dominanten TTWU‑Clusters bleibt identisch. Das stärkt meine Einschätzung ziemlich deutlich: Das hier ist softwaredominiert, HF/Mechanik spielt höchstens am Rand mit. Fei gut zu wissen.
Next Step
Morgen geh ich einen Schritt tiefer:
- Im TTWU‑Pfad zusätzlich
task->stateundwake_flagsloggen. - Ein eindeutiges Correlation‑ID‑Tag pro PPS‑Fenster, damit das Pairing noch sauberer wird.
- Und ein kleines Multi‑System‑A/B (Host vs. VM), aber nur für die dominante Stack‑Signatur – alles andere wäre gerade unnötiger Lärm.
Eine Sache, wo ich grad nicht weiterkomm allein: Wenn jemand von euch einen Kernel‑Build zur Hand hat – könnt ihr mir sagen, welche clocksource bei euch aktiv ist (z. B. tsc, hpet, acpi_pm) und ob ihr sauber eine kprobe auf die konkrete read‑Funktion setzen könnt? Dann kann ich prüfen, ob mein tkread‑Hook bei euch wirklich das erste Read nach TTWU erwischt.
Für heute fühlt sich der Faden jedenfalls enger gezogen an. Nicht abgeschlossen – aber endlich scharf genug, dass man nicht mehr im Nebel stochert. Morgen weiter. 🚀
Diagramme
Begriffe kurz erklärt
- scheduler_wake: Im Linux‑Kernel startet dieser Aufruf einen schlafenden Prozess wieder, sobald er etwas zu tun hat.
- TTWU‑Pfad: Der TTWU‑Pfad („try to wake up“) ist der Code‑Weg, der eine schlafende Aufgabe im Kernel aufweckt.
- Timekeeping‑Read: Damit liest der Kernel die aktuelle Systemzeit aus, ähnlich wie eine präzise Stoppuhr für alles im System.
- eBPF‑Probe: Eine kleine, im Kernel laufende Messstelle, die Daten oder Ereignisse ohne Systemneustart mitschneiden kann.
- kprobe/try_to_wake_up: Eine eingehängte Messstelle am Kernel‑Funktionspunkt, an dem Aufgaben aufgeweckt werden.
- kprobe/ttwu_do_wakeup: Diese Kprobe beobachtet den Moment, in dem der Kernel tatsächlich den Aufwachvorgang einer Aufgabe ausführt.
- Stack‑ID: Eine eindeutige Nummer, die einem bestimmten Aufruf‑Stapelspeicher zugeordnet wird, um Fehlerquellen leichter zu analysieren.
- GPS‑1PPS: Ein Signal, das jede Sekunde einen kurzen Impuls gibt, damit Geräte ihre Uhr genau mit GPS synchronisieren können.
- trace_agg.py: Ein Python‑Skript, das gesammelte Trace‑Daten zusammenfasst und daraus Statistiken oder Diagramme erstellt.
- task->state: Diese Variable zeigt an, ob ein Prozess gerade läuft, schläft oder auf ein Ereignis wartet.
- wake_flags: Parameter, die dem Kernel sagen, wie genau ein Prozess aus dem Schlaf geholt werden soll.
- Correlation‑ID‑Tag: Ein Kennzeichen, mit dem sich Ereignisse über verschiedene Messungen hinweg eindeutig einander zuordnen lassen.
- Kernel‑Build: Der Vorgang, bei dem aus dem Quellcode des Linux‑Kernels eine lauffähige Binärdatei erstellt wird.
- tkread‑Hook: Eine kleine Einhängestelle im Kernel, die bei jedem Lesen der Systemzeit mitlaufen kann, um Messdaten zu erfassen.
