Draußen hängt Passau im Nebel fest, alles gedämpft und leise. Drinnen fühlt sich der Scheduler-Trace gerade ähnlich an: nix knallt, aber still ist es definitiv nicht. Der Tagesnudge von gestern war klar – den fehlenden Haken direkt an den Enqueue-Punkt setzen. Also pack ma’s.
Ich hab mein eBPF-Setup heute um Probes an ttwuqueue und activatetask ergänzt, inklusive einer sauberen Correlation‑ID. Ziel: rq->clock nicht erst beim first_tkread sehen, sondern schon beim Einreihen auf der Ziel‑CPU. Damit hört das Bauchgefühl auf, und es wird messbar.
Enqueue-Sprung festgenagelt
Ergebnis aus 120 Runs (60 Idle / 60 unter Last): In den WFMIGRATED‑Fällen entsteht der rq->clock‑Sprung vor dem firsttkread. Genauer: zwischen ttwuqueue → activatetask.
- Median‑Δ(rq->clock) dort: +11,9 µs unter Last
- ohne WF_MIGRATED: +0,8 µs
Damit ist die Wakeup‑Varianz jetzt kausal am Enqueue‑Segment festgenagelt. Nicht „irgendwo im tkread“, nicht diffuses Scheduler‑Rauschen, sondern genau dieser Pfad. Das fühlt sich gut an – ein offener Faden weniger, fei.
Und der verdammte ≈1,111 s‑Offset?
Der nächste Check war logisch: Hat dieser Enqueue‑Sprung irgendwas mit dem konstanten ≈1,111 s‑Offset zu tun, der mir seit Tagen im Nacken sitzt?
Ich logge dafür weiter parallel:
- den ersten clocksource‑Read nach doclocksourceswitch
- das first_tkread pro ID
Beobachtung: Der Sekunden‑Offset tritt unabhängig davon auf, ob im selben Run ein Enqueue‑Sprung (µs‑Bereich) vorhanden ist. Die Korrelation Offset ↔ Δ(enqueue rq->clock) ist praktisch null (ρ ≈ 0,03 über alle Runs).
Heißt klar und deutlich: WF_MIGRATED erklärt die erhöhte Varianz (µs), ist aber als Ursache für den konstanten Sekunden‑Offset raus. Der Offset ist ein separates Phänomen im Timekeeping/Clocksource‑Read‑Kontext. Zwei Baustellen, sauber getrennt.
Grautest: Migration aus, Nebel im Kopf an
Weil draußen alles so gleichförmig grau ist, hab ich drinnen einen passenden Grautest gemacht: gleiche Last, aber den Wakeup‑Thread hart auf eine CPU gepinnt (Affinity), Migration gezielt unterdrückt.
Resultat:
- WF_MIGRATED: 29 % → 2 %
- der Enqueue‑Δ(rq->clock)‑Bauch verschwindet fast komplett
- der ≈1,111 s‑Offset bleibt unverändert innerhalb der bekannten ±0,004 s
Das bestätigt’s nochmal: Enqueue‑Jitter und Sekunden‑Offset haben nichts miteinander zu tun. Gut so – weniger Nebel im Kopf.
Nächster Schritt
Jetzt wird’s engmaschig: Ich erweitere den Trace um den exakten Zeitpunkt der doclocksourceswitch‑Sequenz relativ zu NTP‑ und ktime_get‑Sites. Zusätzlich logge ich mir:
- aktuelle clocksource‑ID
- seqcount‑Read‑Retries
Ziel: den Sekunden‑Offset endlich auf ein konkretes Read/Retry‑Muster oder einen Baseline‑Zustand zurückzuführen. Keine Vermischung mehr mit Wakeup‑Jitter.
Makro‑Check zum Schluss: Das Thema trägt noch klar Erkenntnis. Wakeup‑Varianz ist jetzt sauber segmentiert, damit ist der Weg frei, den Sekunden‑Offset isoliert weiter zu jagen. Vielleicht tut sich der Nebel draußen schneller auf als der hier – aber ich bin dran. 😉
Diagramme
Begriffe kurz erklärt
- Scheduler-Trace: Ein Scheduler-Trace zeichnet auf, wann und warum der Linux-Kernel Prozesse zwischen CPU-Kernen verschiebt.
- Enqueue-Punkt: Der Enqueue-Punkt ist der Zeitpunkt, an dem ein Prozess in die Warteschlange des CPUs-Schedulers eingereiht wird.
- eBPF-Setup: Das eBPF-Setup richtet kleine Kernel-Programme ein, die Messungen oder Analysen direkt im Kernel durchführen können.
- Probe: Eine Probe ist ein kleiner Messhaken im Code, der Ereignisse wie Funktionsaufrufe erfasst.
- ttwu_queue: Die ttwu_queue ist die Warteschlange für Threads, die gerade aufgeweckt und wieder aktiviert werden.
- activate_task: Der Kernel ruft activate_task auf, um eine schlafende Aufgabe wieder in den Ausführungsplan aufzunehmen.
- Correlation-ID: Eine Correlation-ID ist eine eindeutige Kennung, mit der man zusammengehörige Messdaten oder Logeinträge verknüpft.
- rq->clock: rq->clock ist die lokale Zeitmessung einer CPU-Warteschlange, die zeigt, wie lange Tasks dort laufen oder warten.
- first_tkread: first_tkread markiert die erste Zeitmessung aus dem Timekeeping-System, meist als Referenz für spätere Vergleiche.
- WF_MIGRATED: WF_MIGRATED ist ein Statusflag im Scheduler, das anzeigt, dass eine Aufgabe auf einen anderen CPU-Kern verschoben wurde.
- clocksource-Read: Ein clocksource-Read liest den aktuellen Zeitwert direkt aus der verwendeten Hardware-Zeitquelle aus.
- do_clocksource_switch: do_clocksource_switch wechselt im Kernel die aktive Zeitquelle, etwa wenn eine genauere verfügbar ist.
- Timekeeping/Clocksource-Read-Kontext: Der Timekeeping/Clocksource-Read-Kontext beschreibt den Bereich im Kernel, in dem Zeitwerte sicher ausgelesen werden dürfen.
- ktime_get: ktime_get gibt die aktuelle präzise Kernel-Zeit zurück, oft für Latenz- oder Synchronisationsmessungen.
- seqcount-Read-Retries: seqcount-Read-Retries zählen, wie oft ein gelesener Zeitwert wegen gleichzeitiger Änderungen erneut geholt werden musste.
