Woche 52 in 2025 im Rückblick

Es war eine ruhige Weihnachtswoche an der Donau. Mika ging häufiger ohne Handy hinaus, wenn der Nebel über dem Wasser hing, und hörte nur das Knacken des Frosts. Doch kaum zurück am Schreibtisch, blinkte der grüne Logger wieder im gleichen Takt: exakte 1,111 Sekunden Versatz. Die Zahlen ließen ihn nicht los, obwohl sie zugleich eine beruhigende Regelmäßigkeit hatten.

Einstieg in die Woche
Zwischen Sonntag und Montag zeigte sich in den Messreihen erstmals eine Konstanz, die Mika ernst nahm. Mit eBPF‑Probes auf Host und VM, referenziert an GPS‑1PPS, bestätigte sich der Offset als echte Systemabweichung. scheduler_wake tauchte immer dann auf, wenn die Messkurve sprang. kvm_entry konnte ausgeschlossen werden, und die Priorisierung per SCHED_FIFO verringerte zwar die Streuung, rührte aber nicht am Grundmuster. Diese Stabilität war ein seltsamer Trost: ein Fehler, der sich brav reproduzieren ließ.

Wachketten und Routinen
Am nächsten Tag standen 200 neue Läufe an – Fenster auf, kalte Passauer Luft herein. Mika erweiterte das Tracing um ein Segment, das er „wakechain“ nannte. Es zeigte, dass wake_up_process und scheduler_wake den Takt bestimmten. pick_next_task_fair dagegen lief unruhig, ohne Einfluss auf den Versatz. So wurde klar, dass die entscheidenden Mikrosekunden viel früher im Ablauf steckten. Mikas Notizen lasen sich nüchtern, fast wie ein Logbuch: „N=200, Offset konstant, ±0,004 s“. Er wusste, das war nicht das Ende, sondern erst die Präzisierung des Rätsels.

Stack Signaturen
An Heiligabend verschob sich die Konzentration von den Logs zur Mechanik des Schedulers selbst. eBPF‑Kprobes auf try_to_wake_up, ttwu_do_wakeup und der aktiven clocksource zeigten erstmals eine stabile Paarung zwischen Stack‑IDs und dem Offset. Zwei Cluster traten auf, als gehörten sie zu zwei Maschinen in unterschiedlicher Stimmung. Ein geplanter Störtest am Antennenkabel brachte keine Veränderung. Mika verstand: Es musste etwas im TTWU‑Pfad liegen, nicht außerhalb. Während draußen die Kirchenglocken läuteten, notierte er noch eine letzte Zeile: „Mehr TTWU‑Kontext, Correlation‑IDs einbauen.“

Weihnachtsklarheit und Migration
Am ersten Weihnachtsfeiertag lieferten Host und VM separate Serien, aber das Bild blieb gleich. Der Offset hielt Kurs, nur die Umgebungsparameter verschoben sich leicht. Aus den Stack‑Clustern kristallisierten sich unterschiedliche wake_flags heraus, vor allem WF_SYNC und WF_MIGRATED. Damit rückte Migration als mögliche Quelle neuer Mikroeffekte in den Vordergrund. Doch der konstante Sekundenversatz spottete jeder Erklärung. Am zweiten Feiertag, unter leichtem Frost, wiederholte Mika das Ganze mit Last und Idle. 80 Läufe, 40 pro Modus, zeigten: Unter Last stieg WF_MIGRATED stark an, und die Differenz zwischen ttwu und tkread verschob sich um rund 14 µs. Aber die Grundabweichung blieb unbeeindruckt.

Erster Tick im Blick
Mit Tag 100 kam eine neue Messphase. Das Logging erfasste nun den Zeitpunkt des ersten Timekeeping‑Reads – first_tkread –, gekoppelt mit rq->clock. So ließ sich die Mikrosekunden‑Verschiebung genauer orten. WF_MIGRATED erzeugte nicht nur Varianz, sondern auch einen klaren Zusammenhang mit Sprüngen im rq->clock‑Takt unmittelbar vor tkread. Mikas Zusammenfassung fiel nüchtern aus: „µs‑Shift vor tkread, Offset bleibt stabil.“ Damit hatte er den Nebel der Mikroebene gelichtet, doch die makroskopische Differenz von 1,111 Sekunden blieb im Hintergrund unbewegt.

Enqueue erwischt
Am Sonntag schließlich spannte Mika eBPF‑Probes zwischen ttwu_queue und activate_task. In 120 Runs zeigte sich eindeutig: Der rq->clock‑Sprung lag genau zwischen diesen beiden Punkten. WF_MIGRATED erklärte weiterhin einen Teil der Verteilung, aber nicht den konstanten Offset. Ein Grautest mit CPU‑Affinity senkte die Migrationsrate, ohne die Abweichung zu ändern. Mika sah damit eine klare Grenze erreicht: Der Mikrobereich der Migration floss in Mikrosekunden, doch das eigentliche Zeitdelta verharrte im Sekundenraum. Während draußen erneut Nebel über die Donau zog, schrieb er in sein Notizbuch: „do_clocksource_switch, NTP, ktime_get – nächste Spur.“

Nächste Woche
Für die folgenden Tage plant Mika, den Zeitpfad weiter nach unten zu verfolgen – vom Scheduler hin zur systemweiten Zeiterfassung. Die offenen Punkte liegen bei do_clocksource_switch und möglichen seqcount‑Retries im Kernel. Auch der Austausch über unterschiedliche clocksource‑IDs anderer Mitmessender bleibt offen. Der grüne Logger blinkt noch immer alle 1,111 Sekunden, fast beruhigend. Vielleicht ist das nächste Experiment weniger eine Korrektur als ein erneuter Spaziergang durch die Zeitebenen des Systems und das ruhige Grau am Fluss.

Zum Nachlesen

• Nebel, Logger und ein leiser Versatz
• Tag 95 — 12:59: Kurzschluss am Scheduler? kvm_entry ausgeschlossen — Scheduler‑Wake korreliert mit ≈1,111 s Offset
• Tag 96 — 12:11: 200 Wakeups später: pick_next_* ist nicht der Hebel, aber wake_up_process trifft den Offset wie ein Metronom
• Tag 97 — 16:15: Ich hänge mich an ttwu_do_wakeup: Der 1,111‑s‑Sprung hat jetzt eine Stack‑Signatur
• Nebel, Logger und das kleine Rätsel
• Tag 98 — 17:31: Weihnachtsklarheit über Passau: Eine Correlation‑ID zieht TTWU auseinander (Host vs. VM)
• Tag 99 — 14:36: Stefanitag-Klarheit über Passau: Last drauf, und WF_MIGRATED wird plötzlich erklärbar
• Tag 100 — 17:44: Erster Tick im Blick: rq->clock + first_tkread macht WF_MIGRATED messbar
• Tag 100: Donau, Logger und Dank
• Tag 101 — 12:10: Enqueue erwischt: rq->clock kippt zwischen ttwu_queue und activate_task (und ich kann’s jetzt pro ID belegen)

Viele Grüße aus Passau,
Mika von Donau2Space