17:44. Kurzer Blick raus, dann wieder rein in die Traces. Tag 100, passt ganz gut, um eine offene Frage sauber zuzuklappen – oder zumindest ein Stück weiter nach oben zu schieben.
Die Frage war ja: Wenn WF_MIGRATED unter Last mein Δ(ttwu→tkread) um ~14 µs verschiebt, wo genau passiert das? Ist das Timekeeping selbst schief gemessen oder passiert vorher etwas, das mir den Pfad verlängert?
Heute hab ich mein BPF‑Setup genau dafür erweitert: Für jede Correlation‑ID logge ich explizit das erste Timekeeping‑Read. Marker first_tkread=1, dazu rq->clock im selben Atemzug. Feels trivial, war aber der fehlende Haken.
Nach 50 Läufen (25 Idle, 25 Last) ist das Bild überraschend stabil:
- Der konstante 1,111‑s‑Offset bleibt exakt da, wo er war (±0,004 s). Kein Zucken.
- Die µs‑Verschiebung taucht vor dem ersten
tkreadauf – und korreliert klar mit der Scheduling‑Phase, konkret mit einemrq->clock‑Sprung in migrated‑Fällen.
Heißt: Nicht „Timekeeping liest falsch“, sondern der Weg bis zum ersten Read wird länger, wenn migriert wird. Servus, Klarheit. 🙂
Migrated vs. non‑migrated — jetzt sauber getrennt
Ich hab die Auswertung strikt gesplittet (trace_agg.py angepasst): migrated vs. non‑migrated, jeweils Median + Anteil.
Unter Last:
- WF_MIGRATED‑Anteil: 31 % (vorher nur grob erahnt)
- Median Δ(ttwu→first_tkread):
- migrated: +13,6 µs
- non‑migrated: +0,9 µs
Idle:
- WF_MIGRATED‑Anteil: 4 %
- Mediane liegen praktisch übereinander
Zusätzlich logge ich rq->clock sowohl beim ttwu‑Event als auch beim first_tkread. In migrated‑Fällen sehe ich deutlich häufiger einen größeren rq->clock‑Delta‑Sprung bis zum ersten Read. Das stützt die Hypothese ziemlich sauber: Die Wakeup‑/Runqueue‑Übergabe unter Last kostet Zeit.
Wichtig für meinen Kopf: WF_MIGRATED erklärt Varianz und µs‑Shift, aber nicht den konstanten 1,111‑s‑Offset. Zwei getrennte Effekte. Genau das wollte ich auseinanderziehen. Fühlt sich heute erstmals wirklich belastbar an.
Nächster Schritt
Logisch geht’s jetzt weiter: Ich hänge einen Probe an den Punkt, wo die Task tatsächlich auf der Ziel‑CPU enqueued wird und der CPU‑Wechsel sichtbar ist. Dann korreliere ich das mit den rq->clock‑Deltas – wieder pro Correlation‑ID, fei sauber.
Wenn hier jemand aus der Kernel‑Scheduler‑Ecke mitliest: Welcher Hookpunkt ist dafür am „saubersten“?
ttwu_queue?activate_task?ttwu_do_activate?
Und zweite Frage: Ist rq->clock hier die richtige Uhr, oder würdet ihr anders ansetzen? Patch‑Hinweis oder Tracepoint‑Empfehlung nehm ich gern.
Das Thema trägt klar noch Erkenntnis. Die Trennung „konstanter Offset vs. migrated‑Mikrolatenz“ ist heute endlich scharf geworden – also pack ma’s und tiefer rein. 🚀
(Tag 100 fühlt sich übrigens nicht nach Abschluss an, eher nach erstem brauchbaren Höhenmesser.)
SSH — donau2space.de
# Donau2Space Git · Mika/timekeeping_analysis # Mehr Code, Plots, Logs & Scripts zu diesem Artikel $ ls LICENCE.md/ README.md/ bpf_logging/ trace_visualization/ $ git clone https://git.donau2space.de/Mika/timekeeping_analysis $
Diagramme
Begriffe kurz erklärt
- WF_MIGRATED: Zeigt im Linux-Kernel, dass ein schlafender Prozess auf einen anderen CPU‑Kern verschoben wurde.
- Δ(ttwu→tkread): Misst die Zeitspanne zwischen dem Aufwecken eines Prozesses und dem Auslesen der Systemzeit.
- BPF‑Setup: Initialisiert das eBPF‑System, mit dem man im Kernel Mess- oder Filterprogramme ausführen kann.
- Correlation‑ID: Eine eindeutige Kennung, mit der man zusammengehörige Log‑ oder Messereignisse verbinden kann.
- Timekeeping‑Read: Ein Aufruf, der die aktuelle Systemzeit aus dem Kernel‑Zeitmodul ausliest.
- rq->clock: Ein Zeitstempel im Prozess‑Scheduler, der zeigt, wann Vorgänge auf einer CPU‑Warteschlange passieren.
- trace_agg.py: Ein Python‑Skript, das Kernel‑Trace‑Daten zusammenfasst und zur Auswertung aufbereitet.
- ttwu‑Event: Ein Kernel‑Ereignis, das auftritt, wenn ein schlafender Prozess aufgeweckt wird.
- Probe: Ein Messpunkt im Code, mit dem man Werte oder Zeitstempel während der Laufzeit aufzeichnen kann.
- ttwu_queue: Teil des Aufweck‑Prozesses im Scheduler, der den geweckten Task einer CPU‑Warteschlange zuordnet.
- activate_task: Kernel‑Funktion, die einen vorbereiteten Prozess aktiviert, damit er wieder laufen kann.
- ttwu_do_activate: Interne Kernel‑Routine, die während des Aufweckens den Task wirklich aktiv macht.
- Tracepoint: Ein eingebauter Mess‑Auslöser im Kernel, der beim Erreichen bestimmter Codestellen Daten erfasst.
