feat(diag): hitch flight recorder and non-blocking log (#361)

build.bat

@@ -112,7 +112,7 @@ rem --- Test build (pure-logic sources only; no <windows.h>) -----------------
 rem /wd5285 silences a known doctest 2.4.11 header warning under MSVC /W4.
 cl /nologo /std:c++17 /EHsc /W4 /wd5285 /DWIND_TESTS /I third_party ^
    tests\*.cpp ^
-   src\transform.cpp src\zoom_controller.cpp src\config.cpp src\profiles.cpp src\cursor_mapper.cpp src\lock_detector.cpp src\cursor_lock.cpp src\mouse_ballistics.cpp src\crosshair.cpp src\config_ui\ini_edit.cpp src\logging.cpp src\tray_items.cpp ^
+   src\transform.cpp src\zoom_controller.cpp src\config.cpp src\profiles.cpp src\cursor_mapper.cpp src\lock_detector.cpp src\cursor_lock.cpp src\mouse_ballistics.cpp src\crosshair.cpp src\config_ui\ini_edit.cpp src\logging.cpp src\tray_items.cpp src\hitch_record.cpp ^
    /Fe:wind_tests.exe
 if errorlevel 1 exit /b 1
 "%ROOT%wind_tests.exe"

docs/architecture/12-instrumentation.md

@@ -33,24 +33,68 @@ unit-tested; the Win32 half is excluded from the test build.
   `wind-config.log` from WindConfig.exe. Rotation at 1 MiB over three generations. A second
   instance that cannot open the shared log writes `wind-core-<pid>.log`.
 - **Lines.** `wind::Log(level, category, fmt, ...)` gives
-  `2026-05-31T08:14:22.137Z  WARN  render  <msg>`. Thread-safe, flushes on Warn and Error.
-  **Never log from the per-frame path**; hot paths log per-second summaries.
+  `2026-05-31T08:14:22.137Z  +962862007.114  t57132  WARN  render  <msg>`: precise UTC, the QPC
+  clock in ms (the clock of PresentMon `--qpc_time_ms`, ETW and the tick records) and the thread id.
+- **Non-blocking (#361).** `Log` formats into a lock-free queue (`src/log_queue.h`, 1024 lines)
+  and returns; the `Wind log writer` thread (below normal priority) writes in batches, flushes on
+  Warn and Error, and rotates at runtime. A caller never waits on the disk, an EDR scan or another
+  thread, so the tick and hook threads may log. A full queue drops the line and the writer logs
+  `dropped N lines`. `LogFlush(ms)` blocks until queued lines are on disk (export, crash, shutdown).
+  Hot paths still log exceptional events and summaries, not every frame.
 - **Startup snapshot.** Version and build flavour, OS build (`RtlGetVersion`), CPU, RAM, every
   adapter with driver version, every monitor with resolution, refresh, DPI and rotation, and the
   live config.
 - **Crash dumps.** The unhandled-exception filter writes `wind-crash-<ts>.dmp` and a text summary
   (code, address, faulting module), heap-free from a directory resolved at `LogInit`.
 - **Export diagnostics** (Settings > Preferences) zips the log folder to the Desktop. Files are
   stage-copied first, so the export never touches a live handle. The tray has no export.
-- `diagnostics=1` adds the chattier frame-pacing trace in `%TEMP%\wind_diag.log`.
+- `diagnostics=1` adds the chattier 2 s frame-pacing summary as `diag` lines.
+
+## Hitch recorder (#361)
+
+Every tick fills a `TickRec` (`src/hitch_record.h`): its dt, the pacing wait before it and how
+late that wait returned, its wall time and its thread CPU time (`QueryThreadCycleTime`, calibrated
+against QPC in the first second), and spans for the parts that can block. `SpanScope`
+(`src/tick_span.h`) times a call into the current record from anywhere on the tick thread; it is
+a null check on other threads. Spans: `track`, `color`, `present`, `txwrite` (MagHost writes,
+marshal included), `ix`, `sprite`, `activate`. A ring keeps the last 512 records. Cost: about
+a dozen QPC reads per tick, no allocation, no I/O.
+
+When a zoomed frame exceeds `hitchThresholdPct` (default 150) of the refresh interval,
+`ClassifyHitch` attributes the extra time and a `hitch` line is logged (at most two a second; the
+rest are counted on the next line). `hitchLog=0` turns the lines off.
+
+| cause | meaning | next step |
+|---|---|---|
+| `late-wake` | the pacing wait should have ended, the tick thread was not run | CPU contention: system context, WPR |
+| `compositor-late` | txPace=2: the composite pulse came late, DWM did not compose | DWM/GPU side |
+| `pulse-thread-late` | DWM composed on time, the pulse thread signalled late | its priority |
+| `blocked in X` | the tick was off the CPU inside span X: a wait, or preempted in it | the call in X |
+| `busy in X` | the tick was on the CPU in X: Wind's own work | a code fix |
+| `slow-tick in X` | a long tick in the first second, before CPU time is calibrated | either of the two above |
+| `flush-wait` | the post-tick DwmFlush took longer than a frame | DWM side |
+| `loop-other` | the time went between ticks, outside every measured part | message dispatch |
+
+`untracked` in place of a span means no span covers half the tick: add one. Each line also carries
+engine, pacing mode, level, zoom edge, the wait numbers, the previous tick's work, CPU, flush and
+spans, and the dt of the ticks before it. A `minute:` line summarises each minute that had zoomed
+ticks (ticks, hitches by cause, worst dt, worst wake lateness, tick work).
+
+Every transform zoom-out logs one `txsession session end` line with the teardown split per step
+(cursor show, blanker restore, nudge, clip, trace hand-off, identity park, input transform, pin,
+ghost). The compositor stall after the park happens after the call returns and is not in it.
+
+Threads are named (`Wind tick`, `Wind input hooks`, `Wind composite pulse`, `Wind log writer`),
+so a WPR trace shows them by name.
 
 **Per-second and edge lines** (logged only when worth reading):
 
 | Category | Source | Content |
 |---|---|---|
 | `txwrite` | `TransformModel::noteWrite` | Write count, avg/max ms, writes over 5 ms, failures; only when max > 5 ms or a write failed. A `fails` streak is the shared-runtime tell ([05](05-transform-engine.md)) |
 | `ixwrite` | `TransformModel::noteIxWrite` | Input-transform publish cadence and timing, plus `stomps` |
-| `txsession` | `TransformModel` | `session end maxLevel=..` per transform session |
+| `txsession` | `TransformModel` | `session end maxLevel=.. teardown=..ms (..per step..)` per transform session |
+| `hitch` | `RunTick` | A classified long frame, and the `minute:` summary (see Hitch recorder) |
 | `cursor` | `RunTick`, `diagnostics=1` | Pointer distance from the lens centre at the weld instant. Blind to between-tick lag; use the wobble probes for that |
 | `lock` | `RunTick` | Lock edges and the tell that caused them (`warp-anchor`, `seeded LOCKED at zoom-in`) |
 | `hybrid` | `RunTick` | Engine pick per session |

src/config.cpp

@@ -150,6 +150,8 @@ Config ParseConfig(const std::string& text) {
             else if (key == "panDownMods")      c.panDownMods = std::stoi(val);
             else if (key == "panSpeed")         c.panSpeed = std::stod(val);
             else if (key == "zoomTrace")        c.zoomTrace = std::stoi(val);
+            else if (key == "hitchLog")         c.hitchLog = std::stoi(val);
+            else if (key == "hitchThresholdPct") c.hitchThresholdPct = std::clamp(std::stoi(val), 110, 1000);
             // The chain is split in two: MSVC caps if/else nesting depth (C1061). Keys are unique,
             // so a second chain changes nothing.
             if (key == "hideCursorVk")     c.hideCursorVk = std::stoi(val);
@@ -493,7 +495,7 @@ std::string DefaultIniText() {
                "vsync=1\n"
                "; dwmFlush: 0=plain vsync pacing (default, fewer stutters); 1=align to DWM's composition\n"
                "dwmFlush=0\n"
-               "; diagnostics=1 logs frame timing to %TEMP%\\wind_diag.log (restart to apply)\n"
+               "; diagnostics=1 logs frame timing as diag lines in wind-core.log (restart to apply)\n"
                "diagnostics=0\n"
                "; cursorSensitivity: pan speed multiplier - free panning auto-matches the OS cursor\n"
                ";   (DPI+accel) then scales by this (1.0=exact match); also scales locked-game panning\n"

src/config.h

@@ -72,6 +72,11 @@ struct Config {
     double zoomInSpeed  = 1.0;       // 0.25-4.0
     double zoomOutSpeed = 1.0;       // 0.25-4.0
     int    zoomTrace    = 0;         // 1 = log a zoom-in/zoom-out timeline per zoom (#310, diagnostics)
+    // Hitch recorder (#361): log every long zoomed frame with its classified cause, plus a
+    // per-minute summary. On by default: the record costs ~0.5 us per tick and logs nothing on a
+    // smooth frame. hitchThresholdPct: a frame longer than this % of the refresh interval counts.
+    int    hitchLog     = 1;
+    int    hitchThresholdPct = 150;
     double panSpeed     = 1.0;       // 0.25-4.0; 1.0 = up to 1.25 screens per second; slower at low zoom (smooth curve, KeyPan)
     // Smooth zoom: 0 = linear/constant; 1 = zoom-IN soft-starts (eases up to linear). Shipped on.
     int    smoothZoom = 1;
@@ -92,7 +97,7 @@ struct Config {
     // game the way DwmFlush can. 1 = present immediately then DwmFlush() to align 1:1 with DWM's
     // composition (overrides vsync while zoomed). Hot-reloadable.
     int    dwmFlush         = 0;
-    int    diagnostics      = 0;     // 1 = log frame-timing to wind_diag.log
+    int    diagnostics      = 0;     // 1 = log frame-timing as "diag" lines in wind-core.log
 
     // --- Model selection ----------------------------------------------------
     // Which magnification model runs. "hybrid" (DEFAULT, "Auto" in the UI) constructs render +

src/cursor_blanker.cpp

@@ -1,4 +1,5 @@
 #include "cursor_blanker.h"
+#include "tick_span.h"   // #361: per-tick spans
 namespace wind {
 
 static const UINT kStandardIds[] = {
@@ -28,6 +29,7 @@ CursorBlanker::CursorBlanker() {
 }
 
 void CursorBlanker::blank() {
+    SpanScope span(kSpanCursor);
     if (blanked_) return;
     blanked_ = true;
     for (UINT id : kStandardIds) {
@@ -37,6 +39,7 @@ void CursorBlanker::blank() {
 }
 
 void CursorBlanker::restore() {
+    SpanScope span(kSpanCursor);
     if (!blanked_) return;
     blanked_ = false;
     SystemParametersInfoW(SPI_SETCURSORS, 0, nullptr, 0);

src/cursor_sprite.cpp

@@ -1,4 +1,5 @@
 #include "cursor_sprite.h"
+#include "tick_span.h"   // #361: per-tick spans
 #include "crosshair.h"
 #include "band_window.h"
 #include <cstring>
@@ -114,6 +115,7 @@ void CursorSprite::setLayer(SpriteLayer l) {
 // while ShapeStatus::Hidden is returned, i.e. the cursor is suppressed/hidden
 // or its shape could not be captured this tick.
 CursorSprite::ShapeStatus CursorSprite::refreshShape() {
+    wind::SpanScope span(wind::kSpanShape);
     CURSORINFO info{};
     info.cbSize = sizeof(CURSORINFO);
     if (!GetCursorInfo(&info)) return ShapeStatus::Hidden;
@@ -359,6 +361,7 @@ void CursorSprite::renderMaskShape() {
 // come from here (issue #229: the Inspect crosshair's centered hotspot swapped back to the
 // arrow's tip hotspot with the move deduped, showing the arrow displaced by hotspot * zoom).
 void CursorSprite::moveTo(int desktopX, int desktopY) {
+    wind::SpanScope span(wind::kSpanSprite);
     lastTargetX_ = desktopX; lastTargetY_ = desktopY; haveTarget_ = true;
     SetWindowPos(hwnd_, nullptr, desktopX - hotX_, desktopY - hotY_, 0, 0,
                  SWP_NOSIZE | SWP_NOZORDER | SWP_NOACTIVATE);
@@ -454,6 +457,7 @@ void CursorSprite::renderCrosshair() {
 }
 
 void CursorSprite::showCrosshair() {
+    wind::SpanScope span(wind::kSpanSprite);
     if (!hwnd_) return;
     if (!crosshairMode_) {
         renderCrosshair();
@@ -470,10 +474,12 @@ void CursorSprite::showCrosshair() {
 }
 
 void CursorSprite::show() {
+    wind::SpanScope span(wind::kSpanSprite);
     if (!visible_) { ShowWindow(hwnd_, SW_SHOWNOACTIVATE); visible_ = true; }
     if (pendingHide_) { ShowWindow(pendingHide_, SW_HIDE); pendingHide_ = nullptr; }
 }
 void CursorSprite::hide() {
+    wind::SpanScope span(wind::kSpanSprite);
     if (visible_) { ShowWindow(hwnd_, SW_HIDE); visible_ = false; }
     if (pendingHide_) { ShowWindow(pendingHide_, SW_HIDE); pendingHide_ = nullptr; }
 }

src/hitch_record.cpp

@@ -0,0 +1,167 @@
+// src/hitch_record.cpp - see hitch_record.h. Pure: compiled into the WIND_TESTS build.
+#include "hitch_record.h"
+#include <cstdio>
+
+namespace wind {
+
+const char* TickSpanName(int span) {
+    switch (span) {
+        case kSpanTrack:    return "track";
+        case kSpanColor:    return "color";
+        case kSpanPresent:  return "present";
+        case kSpanTxWrite:  return "txwrite";
+        case kSpanIx:       return "ix";
+        case kSpanSprite:   return "sprite";
+        case kSpanActivate: return "activate";
+        case kSpanCursor:   return "cursor";
+        case kSpanShape:    return "shape";
+    }
+    return "?";
+}
+
+const char* HitchCauseName(HitchCause c) {
+    switch (c) {
+        case HitchCause::None:            return "none";
+        case HitchCause::LateWake:        return "late-wake";
+        case HitchCause::CompositorLate:  return "compositor-late";
+        case HitchCause::PulseThreadLate: return "pulse-thread-late";
+        case HitchCause::Blocked:         return "blocked";
+        case HitchCause::Busy:            return "busy";
+        case HitchCause::SlowTick:        return "slow-tick";
+        case HitchCause::FlushWait:       return "flush-wait";
+        case HitchCause::LoopOther:       return "loop-other";
+    }
+    return "?";
+}
+
+bool IsHitch(const TickRec& cur, double frameMs, int thresholdPct) {
+    if (cur.flags & kTickWoke) return false;          // dt is an idle sleep, not a frame
+    return cur.dtMs > frameMs * thresholdPct / 100.0;
+}
+
+static int DominantSpan(const TickRec& r) {
+    // The present span contains the transform, ix and sprite spans: prefer the most specific
+    // one that explains at least half of the tick, then fall back to the containers.
+    int best = -1; float bestMs = 0;
+    for (int i = 0; i < kSpanCount; ++i) {
+        if (i == kSpanPresent) continue;
+        if (r.span[i] > bestMs) { bestMs = r.span[i]; best = i; }
+    }
+    if (best >= 0 && bestMs >= 0.5f * r.workMs) return best;
+    if (r.span[kSpanPresent] >= 0.5f * r.workMs) return kSpanPresent;
+    return -1;
+}
+
+HitchVerdict ClassifyHitch(const TickRec& prev, const TickRec& cur, double frameMs) {
+    HitchVerdict best{ HitchCause::LoopOther, -1, 0.0f };
+    auto consider = [&](HitchCause c, int span, float ms) {
+        if (ms > best.ms) { best.cause = c; best.span = span; best.ms = ms; }
+    };
+    const float frame = (float)frameMs;
+
+    if (cur.wakeLateMs > 0) consider(HitchCause::LateWake, -1, cur.wakeLateMs);
+
+    if ((cur.flags & kTickPacePulse) && cur.pulseGapMs > frame) {
+        const float excess = cur.pulseGapMs - frame;
+        // DWM composed, but the pulse thread signalled late: that delay is the scheduler's.
+        if (cur.pulseDelayMs > 0 && cur.pulseDelayMs >= 0.5f * excess)
+            consider(HitchCause::PulseThreadLate, -1, cur.pulseDelayMs);
+        else
+            consider(HitchCause::CompositorLate, -1, excess);
+    }
+
+    if (prev.workMs > 0) {
+        const int span = DominantSpan(prev);
+        HitchCause c = HitchCause::SlowTick;          // no CPU time yet: cannot tell which
+        if (prev.cpuMs >= 0)
+            c = (prev.workMs - prev.cpuMs > 0.5f * prev.workMs) ? HitchCause::Blocked : HitchCause::Busy;
+        consider(c, span, prev.workMs);
+    }
+
+    if (prev.flushMs > frame) consider(HitchCause::FlushWait, -1, prev.flushMs - frame);
+
+    const float wait = cur.waitMs > 0 ? cur.waitMs : 0.0f;
+    const float other = cur.dtMs - prev.workMs - prev.flushMs - wait;
+    consider(HitchCause::LoopOther, -1, other);
+    return best;
+}
+
+static const char* EngineName(unsigned f) {
+    return (f & kTickTransform) ? "transform" : (f & kTickRender) ? "render" : "-";
+}
+static const char* PaceName(unsigned f) {
+    return (f & kTickPacePulse) ? "pulse" : (f & kTickPaceTimer) ? "timer"
+         : (f & kTickPaceFlush) ? "dwmflush" : "present";
+}
+
+std::string FormatHitchLine(const TickRec& prev, const TickRec& cur, const HitchVerdict& v,
+                            double frameMs, const float* recentDt, int nRecent, unsigned suppressed) {
+    char b[160];
+    std::string o;
+    std::snprintf(b, sizeof(b), "hitch dt=%.1fms (frame %.1f, %.1fx) cause=%s",
+                  cur.dtMs, frameMs, frameMs > 0 ? cur.dtMs / frameMs : 0.0, HitchCauseName(v.cause));
+    o += b;
+    if (v.cause == HitchCause::Blocked || v.cause == HitchCause::Busy || v.cause == HitchCause::SlowTick)
+        o += std::string(" in ") + (v.span >= 0 ? TickSpanName(v.span) : "untracked");
+    std::snprintf(b, sizeof(b), " %.1fms | eng=%s pace=%s lvl=%.2f%s%s%s", v.ms,
+                  EngineName(prev.flags), PaceName(cur.flags), prev.level,
+                  (prev.flags & kTickEnter) ? " zoom-in" : "", (prev.flags & kTickExit) ? " zoom-out" : "",
+                  (cur.flags & kTickPulseTimeout) ? " pulse-timeout" : "");
+    o += b;
+    std::snprintf(b, sizeof(b), " | wait=%.1f late=%.1f", cur.waitMs, cur.wakeLateMs);
+    o += b;
+    if (cur.flags & kTickPacePulse) {
+        std::snprintf(b, sizeof(b), " pulseGap=%.1f pulseDelay=%.1f", cur.pulseGapMs, cur.pulseDelayMs);
+        o += b;
+    }
+    std::snprintf(b, sizeof(b), " | prev work=%.1f cpu=%.1f flush=%.1f | spans", prev.workMs, prev.cpuMs, prev.flushMs);
+    o += b;
+    bool any = false;
+    for (int i = 0; i < kSpanCount; ++i) {
+        if (prev.span[i] < 0.05f) continue;
+        std::snprintf(b, sizeof(b), " %s=%.1f", TickSpanName(i), prev.span[i]);
+        o += b; any = true;
+    }
+    if (!any) o += " -";
+    if (nRecent > 0 && recentDt) {
+        o += " | recent dt";
+        for (int i = 0; i < nRecent; ++i) { std::snprintf(b, sizeof(b), " %.1f", recentDt[i]); o += b; }
+    }
+    if (suppressed) { std::snprintf(b, sizeof(b), " | +%u more since last line", suppressed); o += b; }
+    return o;
+}
+
+void HitchSummary::addTick(const TickRec& r) {
+    if (r.flags & kTickWoke) return;
+    ++ticks;
+    sumWork += r.workMs;
+    if (r.workMs > maxWork) maxWork = r.workMs;
+    if (r.wakeLateMs > worstLate) worstLate = r.wakeLateMs;
+}
+
+void HitchSummary::addHitch(const TickRec& cur, const HitchVerdict& v) {
+    ++hitches;
+    const int ci = (int)v.cause;
+    if (ci >= 0 && ci < 9) byCause[ci]++;
+    if (cur.dtMs > worstDt) { worstDt = cur.dtMs; worstCause = v.cause; }
+}
+
+std::string HitchSummary::format() const {
+    if (ticks == 0) return std::string();
+    char b[200];
+    std::snprintf(b, sizeof(b), "minute: zoomed ticks=%u hitches=%u worst dt=%.1fms (%s) worst late=%.1fms work avg=%.2f max=%.1fms",
+                  ticks, hitches, worstDt, HitchCauseName(worstCause), worstLate,
+                  ticks ? sumWork / ticks : 0.0, maxWork);
+    std::string o = b;
+    if (hitches) {
+        o += " | by cause";
+        for (int i = 1; i < 9; ++i) {
+            if (!byCause[i]) continue;
+            std::snprintf(b, sizeof(b), " %s=%u", HitchCauseName((HitchCause)i), byCause[i]);
+            o += b;
+        }
+    }
+    return o;
+}
+
+}  // namespace wind