From 2f8cfdb19128aa067d8696186789814a6374d8ad Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Sun, 4 Oct 2026 05:00:30 +0200 Subject: [PATCH 1/2] feat(diag): hitch flight recorder and non-blocking log (#361) Log() now pushes into a lock-free queue and a below-normal writer thread does the disk I/O, so no thread waits on the disk or an EDR scan. Lines carry the QPC ms and thread id. Every tick records its wait, wake lateness, work, CPU time and spans; a long zoomed frame logs a classified hitch line plus a per-minute summary. Zoom-out teardown is timed per step. DiagLog and the txTrace dump no longer write from the tick thread. Threads are named. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01KPUNAWcwghXdHCApcKKjSG --- build.bat | 2 +- docs/architecture/12-instrumentation.md | 52 ++++++- src/config.cpp | 4 +- src/config.h | 7 +- src/cursor_sprite.cpp | 5 + src/hitch_record.cpp | 165 ++++++++++++++++++++ src/hitch_record.h | 103 ++++++++++++ src/input_router.cpp | 1 + src/log_queue.h | 85 ++++++++++ src/logging.cpp | 177 ++++++++++++++++++--- src/logging.h | 16 +- src/mag_host.cpp | 4 + src/main.cpp | 198 ++++++++++++++++++++---- src/tick_span.h | 41 +++++ src/transform_model.cpp | 54 ++++++- src/transform_model.h | 2 + src/version.h | 6 +- tests/test_hitch_record.cpp | 119 ++++++++++++++ tests/test_log_queue.cpp | 69 +++++++++ tests/test_logging.cpp | 7 + 20 files changed, 1046 insertions(+), 71 deletions(-) create mode 100644 src/hitch_record.cpp create mode 100644 src/hitch_record.h create mode 100644 src/log_queue.h create mode 100644 src/tick_span.h create mode 100644 tests/test_hitch_record.cpp create mode 100644 tests/test_log_queue.cpp diff --git a/build.bat b/build.bat index b0e63c08..82eb5b91 100644 --- a/build.bat +++ b/build.bat @@ -112,7 +112,7 @@ rem --- Test build (pure-logic sources only; no ) ----------------- 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" diff --git a/docs/architecture/12-instrumentation.md b/docs/architecture/12-instrumentation.md index 138a5026..338cf09d 100644 --- a/docs/architecture/12-instrumentation.md +++ b/docs/architecture/12-instrumentation.md @@ -33,8 +33,14 @@ 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-.log`. - **Lines.** `wind::Log(level, category, fmt, ...)` gives - `2026-05-31T08:14:22.137Z WARN render `. 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 `: 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. @@ -42,7 +48,44 @@ unit-tested; the Win32 half is excluded from the test build. (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): @@ -50,7 +93,8 @@ unit-tested; the Win32 half is excluded from the test build. |---|---|---| | `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 | diff --git a/src/config.cpp b/src/config.cpp index b89d1038..74297d63 100644 --- a/src/config.cpp +++ b/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" diff --git a/src/config.h b/src/config.h index fc577cf2..5a2d9289 100644 --- a/src/config.h +++ b/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 + diff --git a/src/cursor_sprite.cpp b/src/cursor_sprite.cpp index cf989f20..fb9dbc7b 100644 --- a/src/cursor_sprite.cpp +++ b/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 @@ -359,6 +360,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 +456,7 @@ void CursorSprite::renderCrosshair() { } void CursorSprite::showCrosshair() { + wind::SpanScope span(wind::kSpanSprite); if (!hwnd_) return; if (!crosshairMode_) { renderCrosshair(); @@ -470,10 +473,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; } } diff --git a/src/hitch_record.cpp b/src/hitch_record.cpp new file mode 100644 index 00000000..a4b7c4b2 --- /dev/null +++ b/src/hitch_record.cpp @@ -0,0 +1,165 @@ +// src/hitch_record.cpp - see hitch_record.h. Pure: compiled into the WIND_TESTS build. +#include "hitch_record.h" +#include + +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"; + } + 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(cur.flags), PaceName(cur.flags), cur.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 diff --git a/src/hitch_record.h b/src/hitch_record.h new file mode 100644 index 00000000..2aefe177 --- /dev/null +++ b/src/hitch_record.h @@ -0,0 +1,103 @@ +// src/hitch_record.h +// Per-tick flight recorder and hitch classifier (#361). Pure (no ): the tick loop fills +// TickRec with QPC spans and thread CPU time; this file decides what a long frame was and renders +// the log line. Unit-tested in tests/test_hitch_record.cpp. +// +// The question it answers is not "was there a hitch" but "where did the extra time go": +// - late wake: the pacing wait should have returned, Wind's thread was not run yet +// - compositor late: (txPace=2) the composite pulse itself came late, DWM did not compose +// - pulse thread late:(txPace=2) DWM composed on time, the pulse thread was not run yet +// - blocked in X: the tick was off the CPU inside call X (a wait, or preempted in it) +// - busy in X: the tick was on the CPU in X (Wind's own work) +// - slow tick in X: long tick before the CPU clock is calibrated (first second): either of the two +// - flush wait: the post-tick DwmFlush took longer than a frame (compositor) +// - loop other: the time went between ticks, outside every measured part +#pragma once +#include + +namespace wind { + +enum TickSpan : int { + kSpanTrack = 0, // focus tracker hand-off and snapshot + kSpanColor, // colour filter + kSpanPresent, // the model's present (everything a zoomed frame does) + kSpanTxWrite, // transform writes (MagSetFullscreenTransform, marshalled to the owner thread) + kSpanIx, // input-transform publish and read-back + kSpanSprite, // cursor sprite window moves and show/hide + kSpanActivate, // zoom-in / zoom-out session start and end + kSpanCount +}; +const char* TickSpanName(int span); + +enum TickFlag : unsigned { + kTickWoke = 1u << 0, // first tick after an idle sleep: dt is the sleep, never a hitch + kTickEnter = 1u << 1, // zoom-in tick + kTickExit = 1u << 2, // zoom-out tick + kTickTransform = 1u << 3, // engine of this tick + kTickRender = 1u << 4, + kTickPacePulse = 1u << 5, // paced by the composite pulse (txPace=2) + kTickPulseTimeout = 1u << 6, // the pulse wait timed out (backfill tick) + kTickPaceTimer = 1u << 7, // paced by the waitable timer + kTickPaceFlush = 1u << 8, // paced by a post-tick DwmFlush +}; + +struct TickRec { + long long qpcStart = 0; // QPC at tick start + float dtMs = 0; // tick start to tick start (the on-screen frame interval) + float waitMs = -1; // pacing wait just before this tick; -1 = none + float wakeLateMs = -1; // how long after the wait should have ended it returned; -1 = unknown + float pulseGapMs = -1; // txPace=2: interval between the last two composite pulses + float pulseDelayMs = -1; // txPace=2: DWM compose time to the pulse thread's signal + float workMs = 0; // the tick's own wall time + float cpuMs = -1; // the tick thread's CPU time inside it; -1 = not calibrated yet + float flushMs = 0; // post-tick DwmFlush wait + float span[kSpanCount] = {}; + float level = 1.0f; + unsigned flags = 0; +}; + +enum class HitchCause { None, LateWake, CompositorLate, PulseThreadLate, Blocked, Busy, SlowTick, FlushWait, LoopOther }; +const char* HitchCauseName(HitchCause c); + +struct HitchVerdict { + HitchCause cause = HitchCause::None; + int span = -1; // Blocked/Busy: the dominant span, -1 = outside every span + float ms = 0; // the time attributed to the cause +}; + +// cur saw a long dt. prev is the tick before it: its work and flush are inside cur.dtMs. +bool IsHitch(const TickRec& cur, double frameMs, int thresholdPct); +HitchVerdict ClassifyHitch(const TickRec& prev, const TickRec& cur, double frameMs); + +// "hitch dt=41.2ms (frame 6.9) cause=late-wake 31.0ms | wait=33.1 late=31.0 ... | recent dt 6.9,7.0" +// recentDt: the dt of the ticks before prev, oldest first (may be null when nRecent is 0). +std::string FormatHitchLine(const TickRec& prev, const TickRec& cur, const HitchVerdict& v, + double frameMs, const float* recentDt, int nRecent, unsigned suppressed); + +// A fixed ring of the last N tick records. No allocation after construction. +class TickRing { +public: + static const int kCap = 512; + void push(const TickRec& r) { buf_[head_ % kCap] = r; ++head_; } + int size() const { return head_ < kCap ? (int)head_ : kCap; } + // back(0) = newest. Caller keeps i < size(). + const TickRec& back(int i) const { return buf_[(head_ - 1 - (unsigned long long)i) % kCap]; } +private: + TickRec buf_[kCap]; + unsigned long long head_ = 0; +}; + +// Per-minute roll-up of zoomed ticks, so a quiet minute and a rough one read differently. +struct HitchSummary { + unsigned ticks = 0, hitches = 0; + unsigned byCause[9] = {}; + float worstDt = 0, worstLate = 0, maxWork = 0; + double sumWork = 0; + HitchCause worstCause = HitchCause::None; + void addTick(const TickRec& r); + void addHitch(const TickRec& cur, const HitchVerdict& v); + std::string format() const; // empty when there were no zoomed ticks + void reset() { *this = HitchSummary{}; } +}; + +} // namespace wind diff --git a/src/input_router.cpp b/src/input_router.cpp index cbe7eaff..5bb3dc93 100644 --- a/src/input_router.cpp +++ b/src/input_router.cpp @@ -479,6 +479,7 @@ static DWORD WINAPI HookThreadProc(LPVOID) { // the hooks, so it can never starve anything else, and it stops the whole system's input // waiting on us (a late hook thread delays input for EVERY process, not just ours). SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_TIME_CRITICAL); + SetThreadDescription(GetCurrentThread(), L"Wind input hooks"); // names it in WPA (#361) HMODULE hmod = GetModuleHandleW(nullptr); g_mouseHook = SetWindowsHookExW(WH_MOUSE_LL, MouseProc, hmod, 0); // Keyboard hook shares this thread (keystrokes are far rarer than mouse moves, so it adds no diff --git a/src/log_queue.h b/src/log_queue.h new file mode 100644 index 00000000..b690bab0 --- /dev/null +++ b/src/log_queue.h @@ -0,0 +1,85 @@ +// src/log_queue.h +// Bounded multi-producer / single-consumer queue for log lines (#361). Pure (no ). +// +// The point is that a producer NEVER waits: not on the disk, not on the consumer, not on a lock +// another thread holds while it is preempted. That is what lets the tick and hook threads log. +// A full queue drops the entry and returns false; the caller counts drops. +// +// Algorithm: Dmitry Vyukov's bounded MPMC queue (per-cell sequence numbers), used here with one +// consumer. A producer claims a cell with one CAS, fills it in place, then publishes it with a +// release store. A producer preempted between claim and publish delays only the consumer (which +// sees the cell as not ready yet), never another producer. +#pragma once +#include +#include + +namespace wind { + +#ifdef _MSC_VER +#pragma warning(push) +#pragma warning(disable : 4324) // padding from the alignas below is the point +#endif + +template +class LogQueue { + static_assert(N >= 2 && (N & (N - 1)) == 0, "N must be a power of two"); +public: + LogQueue() { + for (size_t i = 0; i < N; ++i) cells_[i].seq.store(i, std::memory_order_relaxed); + } + LogQueue(const LogQueue&) = delete; + LogQueue& operator=(const LogQueue&) = delete; + + // fill(T&) writes the entry in place. Returns false (and does not call fill) when full. + template + bool push(F&& fill) { + size_t pos = enq_.load(std::memory_order_relaxed); + Cell* c; + for (;;) { + c = &cells_[pos & (N - 1)]; + const size_t seq = c->seq.load(std::memory_order_acquire); + const ptrdiff_t diff = (ptrdiff_t)seq - (ptrdiff_t)pos; + if (diff == 0) { + if (enq_.compare_exchange_weak(pos, pos + 1, std::memory_order_relaxed)) break; + } else if (diff < 0) { + return false; // full + } else { + pos = enq_.load(std::memory_order_relaxed); // another producer took it + } + } + fill(c->value); + c->seq.store(pos + 1, std::memory_order_release); + return true; + } + + // Single consumer only. consume(const T&) reads the entry. Returns false when the next entry + // is not published yet (empty, or its producer is still filling it). + template + bool pop(F&& consume) { + Cell* c = &cells_[deq_ & (N - 1)]; + const size_t seq = c->seq.load(std::memory_order_acquire); + if ((ptrdiff_t)seq - (ptrdiff_t)(deq_ + 1) != 0) return false; + consume(c->value); + c->seq.store(deq_ + N, std::memory_order_release); + ++deq_; + return true; + } + + // Single consumer only: true when pop() would succeed right now. + bool ready() const { + const Cell& c = cells_[deq_ & (N - 1)]; + return (ptrdiff_t)c.seq.load(std::memory_order_acquire) - (ptrdiff_t)(deq_ + 1) == 0; + } + +private: + struct Cell { std::atomic seq; T value; }; + Cell cells_[N]; + alignas(64) std::atomic enq_{0}; + alignas(64) size_t deq_ = 0; // consumer-owned +}; + +#ifdef _MSC_VER +#pragma warning(pop) +#endif + +} // namespace wind diff --git a/src/logging.cpp b/src/logging.cpp index 1dfaa645..4e129b38 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -39,6 +39,17 @@ std::string FormatLogLine(unsigned long long tsMsUtc, LogLevel lvl, return out; } +std::string FormatLogLineEx(unsigned long long tsMsUtc, double qpcMs, unsigned tid, LogLevel lvl, + const char* category, const std::string& msg) { + std::string base = FormatLogLine(tsMsUtc, lvl, category, msg); + char mid[48]; + std::snprintf(mid, sizeof(mid), " +%.3f t%u", qpcMs, tid); + // Insert after the timestamp (always the first 24 chars: "YYYY-MM-DDTHH:MM:SS.mmmZ"). + const size_t tsLen = base.find(' '); + base.insert(tsLen == std::string::npos ? base.size() : tsLen, mid); + return base; +} + bool ShouldRotate(unsigned long long currentSizeBytes, unsigned long long maxBytes) { return currentSizeBytes >= maxBytes; } @@ -74,10 +85,12 @@ std::string BuildSnapshot(const SystemInfo& si) { #include #include #include +#include #include #include #include #include "config_path.h" +#include "log_queue.h" #include "version.h" #pragma comment(lib, "advapi32.lib") #pragma comment(lib, "dbghelp.lib") @@ -87,13 +100,34 @@ std::string BuildSnapshot(const SystemInfo& si) { namespace wind { namespace { - HANDLE g_logFile = INVALID_HANDLE_VALUE; - std::mutex g_logMutex; + // Writer-thread state (#361). Producers touch only g_q, the atomics and g_wakeEvt. + struct LogEntry { + unsigned long long utcMs; + long long qpc; + unsigned tid; + LogLevel lvl; + char cat[16]; + char msg[1024]; + }; + LogQueue g_q; // ~1 MiB, static: no allocation on the log path + std::atomic g_running{false}; + std::atomic g_writerIdle{false}; // the writer is (about to be) asleep: wake it + std::atomic g_flushReqGen{0}, g_flushDoneGen{0}; + std::atomic g_pushed{0}, g_flushedUpTo{0}, g_dropped{0}; + HANDLE g_wakeEvt = nullptr; + HANDLE g_writer = nullptr; + long long g_qpcFreq = 1; + + HANDLE g_logFile = INVALID_HANDLE_VALUE; // writer-owned after LogInit + std::mutex g_logMutex; // LogInit / LogShutdown only, never Log std::wstring g_logPath; + std::wstring g_logDir, g_logStem; + bool g_ownsBase = false; // false = per-PID fallback file: never rotate it + unsigned long long g_fileBytes = 0; wchar_t g_crashDir[MAX_PATH] = L""; // crash dir pre-resolved at LogInit; handler builds paths heap-free unsigned long long NowMsUtc() { - FILETIME ft; GetSystemTimeAsFileTime(&ft); // 100ns ticks since 1601 + FILETIME ft; GetSystemTimePreciseAsFileTime(&ft); // 100ns ticks since 1601 ULARGE_INTEGER u; u.LowPart = ft.dwLowDateTime; u.HighPart = ft.dwHighDateTime; // 1601->1970 offset in 100ns units = 116444736000000000. return (u.QuadPart - 116444736000000000ULL) / 10000ULL; @@ -168,6 +202,75 @@ static void PruneStrayPidLogs(const std::wstring& dir) { } } +// The writer thread: drains the queue, formats, writes in batches, flushes when a Warn/Error went +// by or a LogFlush asked, rotates at the cap. Below normal priority: nothing waits on it except +// LogFlush callers (export, crash, shutdown). +static void WriterAppend(const std::string& batch) { + if (batch.empty() || g_logFile == INVALID_HANDLE_VALUE) return; + DWORD wrote = 0; + WriteFile(g_logFile, batch.data(), (DWORD)batch.size(), &wrote, nullptr); + g_fileBytes += wrote; +} + +static void WriterRotateIfNeeded() { + if (!g_ownsBase || !ShouldRotate(g_fileBytes, kLogMaxBytes)) return; + FlushFileBuffers(g_logFile); + CloseHandle(g_logFile); + RotateIfNeeded(g_logDir, g_logStem); + g_logFile = CreateFileW(g_logPath.c_str(), FILE_APPEND_DATA, FILE_SHARE_READ, + nullptr, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, nullptr); + g_fileBytes = 0; +} + +static DWORD WINAPI LogWriterMain(LPVOID) { + std::string batch; + batch.reserve(64 * 1024); + for (;;) { + const unsigned long long reqGen = g_flushReqGen.load(); // before the drain: covers its lines + bool needFlush = reqGen != g_flushDoneGen.load(); + unsigned long long n = 0; + auto format = [&](const LogEntry& e) { + const double qpcMs = double(e.qpc) * 1000.0 / double(g_qpcFreq); + batch += FormatLogLineEx(e.utcMs, qpcMs, e.tid, e.lvl, e.cat, e.msg); + batch += "\r\n"; + if (e.lvl != LogLevel::Info) needFlush = true; + }; + while (g_q.pop(format)) { + ++n; + if (batch.size() > 60 * 1024) { WriterAppend(batch); batch.clear(); } + } + const unsigned long long dropped = g_dropped.exchange(0); + if (dropped) { + LARGE_INTEGER q; QueryPerformanceCounter(&q); + char m[96]; std::snprintf(m, sizeof(m), "dropped %llu lines (queue full)", dropped); + batch += FormatLogLineEx(NowMsUtc(), double(q.QuadPart) * 1000.0 / double(g_qpcFreq), + GetCurrentThreadId(), LogLevel::Warn, "log", m); + batch += "\r\n"; + needFlush = true; + } + WriterAppend(batch); + batch.clear(); + if (needFlush && g_logFile != INVALID_HANDLE_VALUE) FlushFileBuffers(g_logFile); + g_flushedUpTo.fetch_add(n); + g_flushDoneGen.store(reqGen); + WriterRotateIfNeeded(); + if (!g_running.load()) { if (!g_q.ready()) break; continue; } + // Sleep until a producer wakes us. Dekker-style handshake with Log(): announce idle, then + // re-check, so a line published between the drain and the wait is never stranded. + g_writerIdle.store(true); + std::atomic_thread_fence(std::memory_order_seq_cst); + if (!g_q.ready() && g_flushReqGen.load() == g_flushDoneGen.load() && g_running.load()) + WaitForSingleObject(g_wakeEvt, 1000); + g_writerIdle.store(false); + } + return 0; +} + +static void WakeWriter() { + std::atomic_thread_fence(std::memory_order_seq_cst); + if (g_writerIdle.load() && g_writerIdle.exchange(false) && g_wakeEvt) SetEvent(g_wakeEvt); +} + void LogInit(const wchar_t* processTag) { std::lock_guard lk(g_logMutex); if (g_logFile != INVALID_HANDLE_VALUE) return; // idempotent: never leak a prior handle @@ -177,6 +280,7 @@ void LogInit(const wchar_t* processTag) { PruneStrayPidLogs(dir); std::wstring stem = std::wstring(L"wind-") + processTag; std::wstring base = dir + L"\\" + stem + L".log"; + g_logDir = dir; g_logStem = stem; // Probe whether we can own the shared log. If another instance already holds it (the brief // single-instance-refusal overlap), fall back to a per-PID file so we (a) never rotate or // corrupt the active instance's log and (b) still capture our own startup/refusal trail. @@ -186,31 +290,65 @@ void LogInit(const wchar_t* processTag) { g_logPath = dir + L"\\" + stem + L"-" + std::to_wstring(GetCurrentProcessId()) + L".log"; g_logFile = CreateFileW(g_logPath.c_str(), FILE_APPEND_DATA, FILE_SHARE_READ, nullptr, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, nullptr); - return; + g_ownsBase = false; + } else { + CloseHandle(probe); // release before rotating (cannot rename a file we hold open) + RotateIfNeeded(dir, stem); // safe: we are the sole owner of the base log + g_logPath = base; + g_logFile = CreateFileW(base.c_str(), FILE_APPEND_DATA, FILE_SHARE_READ, + nullptr, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, nullptr); + g_ownsBase = true; } - CloseHandle(probe); // release before rotating (cannot rename a file we hold open) - RotateIfNeeded(dir, stem); // safe: we are the sole owner of the base log - g_logPath = base; - g_logFile = CreateFileW(base.c_str(), FILE_APPEND_DATA, FILE_SHARE_READ, - nullptr, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, nullptr); + if (g_logFile == INVALID_HANDLE_VALUE) return; + LARGE_INTEGER sz{}; if (GetFileSizeEx(g_logFile, &sz)) g_fileBytes = (unsigned long long)sz.QuadPart; + LARGE_INTEGER f; QueryPerformanceFrequency(&f); g_qpcFreq = f.QuadPart > 0 ? f.QuadPart : 1; + g_wakeEvt = CreateEventW(nullptr, FALSE, FALSE, nullptr); + g_running.store(true); + g_writer = CreateThread(nullptr, 0, LogWriterMain, nullptr, 0, nullptr); + if (!g_writer) { g_running.store(false); return; } + SetThreadPriority(g_writer, THREAD_PRIORITY_BELOW_NORMAL); + SetThreadDescription(g_writer, L"Wind log writer"); } void Log(LogLevel lvl, const char* category, const char* fmt, ...) { - char msg[1024]; + if (!g_running.load(std::memory_order_relaxed)) return; + LARGE_INTEGER q; QueryPerformanceCounter(&q); + const unsigned long long utc = NowMsUtc(); + const unsigned tid = GetCurrentThreadId(); va_list ap; va_start(ap, fmt); - _vsnprintf_s(msg, sizeof(msg), _TRUNCATE, fmt, ap); + const bool ok = g_q.push([&](LogEntry& e) { + e.utcMs = utc; e.qpc = q.QuadPart; e.tid = tid; e.lvl = lvl; + strncpy_s(e.cat, category ? category : "", _TRUNCATE); + _vsnprintf_s(e.msg, sizeof(e.msg), _TRUNCATE, fmt, ap); + }); va_end(ap); - std::string line = FormatLogLine(NowMsUtc(), lvl, category, msg); - line += "\r\n"; - std::lock_guard lk(g_logMutex); - if (g_logFile == INVALID_HANDLE_VALUE) return; - DWORD wrote = 0; - WriteFile(g_logFile, line.data(), (DWORD)line.size(), &wrote, nullptr); - if (lvl != LogLevel::Info) FlushFileBuffers(g_logFile); + if (ok) g_pushed.fetch_add(1); else g_dropped.fetch_add(1); + WakeWriter(); +} + +bool LogFlush(unsigned timeoutMs) { + if (!g_running.load()) return false; + const unsigned long long target = g_pushed.load(); + const unsigned long long until = GetTickCount64() + timeoutMs; + const unsigned long long gen = g_flushReqGen.fetch_add(1) + 1; + if (g_wakeEvt) SetEvent(g_wakeEvt); + // The writer publishes the generation after the file flush that covered it. + while (g_flushedUpTo.load() < target || g_flushDoneGen.load() < gen) { + if (GetTickCount64() >= until) return false; + Sleep(1); + } + return true; } void LogShutdown() { std::lock_guard lk(g_logMutex); + if (g_writer) { + g_running.store(false); + if (g_wakeEvt) SetEvent(g_wakeEvt); + WaitForSingleObject(g_writer, 2000); // the writer drains the queue before it exits + CloseHandle(g_writer); + g_writer = nullptr; + } if (g_logFile != INVALID_HANDLE_VALUE) { FlushFileBuffers(g_logFile); CloseHandle(g_logFile); @@ -220,6 +358,7 @@ void LogShutdown() { void WriteCrashReport(void* exceptionPointers) { auto* ep = reinterpret_cast(exceptionPointers); + LogFlush(300); // the writer thread still runs: get the queued lines on disk first // Heap-free path building -- g_crashDir was pre-resolved at LogInit. unsigned long long ts = NowMsUtc(); @@ -458,7 +597,7 @@ std::wstring ExportDiagnosticsToDesktop() { return L""; // Flush our own buffered lines so the copy is current (other processes' written-but-unflushed // lines are still readable by CopyFileW via the OS cache). - { std::lock_guard lk(g_logMutex); if (g_logFile != INVALID_HANDLE_VALUE) FlushFileBuffers(g_logFile); } + LogFlush(1000); std::wstring dest = std::wstring(desktop) + L"\\Wind-diagnostics-" + std::to_wstring(NowMsUtc()) + L".zip"; if (!ZipLogDir(dest.c_str())) return L""; return dest; diff --git a/src/logging.h b/src/logging.h index 0b11f15f..cbe97304 100644 --- a/src/logging.h +++ b/src/logging.h @@ -18,6 +18,12 @@ const char* LogLevelName(LogLevel lvl); std::string FormatLogLine(unsigned long long tsMsUtc, LogLevel lvl, const char* category, const std::string& msg); +// The line the runtime writes (#361): FormatLogLine plus the QPC time in ms (the same clock as +// PresentMon --qpc_time_ms, ETW and Wind's tick records) and the logging thread id: +// "2026-05-31T08:14:22.137Z +123456.789 t4242 WARN render " +std::string FormatLogLineEx(unsigned long long tsMsUtc, double qpcMs, unsigned tid, LogLevel lvl, + const char* category, const std::string& msg); + // Rotation policy. Returns true if a file of `currentSizeBytes` should be rotated before the // next write. maxBytes is the per-file cap (the backend uses 1 MiB). bool ShouldRotate(unsigned long long currentSizeBytes, unsigned long long maxBytes); @@ -56,9 +62,15 @@ std::string BuildSnapshot(const SystemInfo& si); // processTag is a short, filename-safe tag: "core" -> wind-core.log, "config" -> wind-config.log. // Resolves the log dir, rotates if the existing file is at/over kLogMaxBytes, opens for append. void LogInit(const wchar_t* processTag); -// Append one event line. Thread-safe. Flushes on Warn/Error. NEVER call from the per-frame path. +// Queue one event line. Thread-safe and NON-BLOCKING (#361): the caller formats into a lock-free +// queue and a low-priority writer thread does the disk I/O (and the flush on Warn/Error). A full +// queue drops the line and the writer reports the count. Safe on the tick and hook threads, but +// per-frame paths should still log summaries or exceptional events, not every frame. void Log(LogLevel lvl, const char* category, const char* fmt, ...); -void LogShutdown(); // flush + close +// Wait (up to timeoutMs) until every line queued before the call is on disk and flushed. +// Blocks the caller: for export, crash and shutdown paths only. +bool LogFlush(unsigned timeoutMs); +void LogShutdown(); // drain, flush, stop the writer, close // Gather the machine/display/config snapshot and write it to the log. buildFlavor is "normal" or // "uiaccess"; configDump is the live config rendered as key=value lines (may be empty for the diff --git a/src/mag_host.cpp b/src/mag_host.cpp index 4e90e4c2..df90809a 100644 --- a/src/mag_host.cpp +++ b/src/mag_host.cpp @@ -1,4 +1,5 @@ #include "mag_host.h" +#include "tick_span.h" // #361: per-tick spans #include "mag_thread.h" #include "logging.h" #include @@ -97,6 +98,7 @@ bool MagHost::setSamplingMode(unsigned mode) { bool MagHost::setTransform(float zoom, int offX, int offY, int tx, int ty, bool fastPan) { if (!initialized_) return false; + SpanScope span(kSpanTxWrite); // includes the marshal to the owner thread // The hot path. Inline (zero marshalling) when the caller IS the owner - which is the whole // point of moving ownership to the hook thread. return MagThreadInvoke([=]() -> bool { @@ -118,6 +120,7 @@ bool MagHost::setTransformOwned(float zoom, int offX, int offY, int tx, int ty, bool MagHost::setInputTransform(bool active, const RECT& src, const RECT& dst) { if (!initialized_) return false; + SpanScope span(kSpanIx); // By value (issue #274): MagThreadInvoke's contract is that the callable owns what it uses. return MagThreadInvoke([active, src, dst]() -> bool { RECT s = src, d = dst; // API takes non-const LPRECT @@ -127,6 +130,7 @@ bool MagHost::setInputTransform(bool active, const RECT& src, const RECT& dst) { bool MagHost::getInputTransform(bool& active, RECT& src, RECT& dst) { if (!initialized_) return false; + SpanScope span(kSpanIx); // Results travel through a heap block the callable co-owns, and reach the caller's // out-params only after a successful invoke, on the caller's own thread (issue #274). struct Out { BOOL en = FALSE; RECT s{}, d{}; }; diff --git a/src/main.cpp b/src/main.cpp index ab4eb3be..d0bf8feb 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -17,6 +17,7 @@ #include "engine_pick.h" #include #include +#include // __rdtsc: thread cycle calibration (#361) #include "hook_transform.h" // inline transform writes from the mouse hook (issue #206) #include "mag_thread.h" #include "mpo_boot.h" @@ -30,6 +31,8 @@ #include "hdr_info.h" // issue #288 #include "cursor_tint.h" // tinted pointer at 1x (#288) #include "transform_model.h" +#include "hitch_record.h" // hitch recorder (#361) +#include "tick_span.h" #include "input_router.h" #include "cursor_mapper.h" #include "zoom_controller.h" @@ -51,13 +54,24 @@ // drooping composition backfills ticks instead of dragging the whole pipeline down with it. // Started lazily on first use; harmless at idle (DwmFlush at composition rate, no work between). static HANDLE g_compEvt = nullptr; +// Hitch recorder (#361): when the pulse thread signalled, the signal before that, and DWM's own +// compose time for that composite. Lets a long frame say whether DWM composed late or the pulse +// thread itself was not run. Written by the pulse thread only; torn reads only blur one record. +static std::atomic g_pulseQpc{0}, g_pulsePrevQpc{0}, g_pulseComposeQpc{0}; static void EnsureCompositePulse() { if (g_compEvt) return; g_compEvt = CreateEventW(nullptr, FALSE, FALSE, nullptr); // auto-reset if (!g_compEvt) return; HANDLE th = CreateThread(nullptr, 0, [](LPVOID) -> DWORD { + SetThreadDescription(GetCurrentThread(), L"Wind composite pulse"); for (;;) { if (DwmFlush() != S_OK) Sleep(50); // DWM restarting: back off, keep trying + DWM_TIMING_INFO ti{}; ti.cbSize = sizeof(ti); + const long long comp = SUCCEEDED(DwmGetCompositionTimingInfo(nullptr, &ti)) ? (long long)ti.qpcCompose : 0; + LARGE_INTEGER q; QueryPerformanceCounter(&q); + g_pulsePrevQpc.store(g_pulseQpc.load(std::memory_order_relaxed), std::memory_order_relaxed); + g_pulseComposeQpc.store(comp, std::memory_order_relaxed); + g_pulseQpc.store(q.QuadPart, std::memory_order_release); SetEvent(g_compEvt); } return 0; @@ -307,6 +321,20 @@ struct TickState { unsigned long long lastActiveMs = 0; // Zoom timeline (#310, zoomTrace=1): one log line per zoom-in and per zoom-out. double lastTickWorkMs = 0; // the previous RunTick's own work time + // Hitch recorder (#361): the tick being recorded, the ring of finished ones, the pacing wait + // measured by the loop for the next tick, and the rate limit / per-minute roll-up. + struct HitchState { + wind::TickRing ring; + wind::TickRec cur; + bool havePrev = false; + float pendWait = -1, pendLate = -1, pendPulseGap = -1, pendPulseDelay = -1; + unsigned pendFlags = 0; + wind::HitchSummary minute; + unsigned long long minuteStartMs = 0, lineWindowMs = 0; + unsigned linesInWindow = 0, suppressed = 0; + long long calQpc0 = 0; unsigned long long calTsc0 = 0; + double cyclesPerMs = 0; // thread cycle counter units per ms, measured at startup + } hitch; struct ZoomTimeline { bool armed = false, outPending = false; int step = 0; long long press = 0, start = 0; @@ -751,15 +779,12 @@ static void EndGameInspect(TickState& t) { wind::Log(wind::LogLevel::Info, "inspect", "game-inspect ended (foreground returned)"); } -// Append a line to %TEMP%\wind_diag.log (frame-pacing diagnostics; gated on diagnostics=1). -// %TEMP% so it works for the Program Files deploy too (its own dir isn't writable). +// Frame-pacing diagnostics (diagnostics=1) as "diag" lines in wind-core.log. Formerly its own +// fopen/append file in %TEMP% from the tick thread; now a queue push like every log line (#361). static void DiagLog(const char* fmt, ...) { - char path[MAX_PATH]; DWORD n = GetTempPathA(MAX_PATH, path); - if (n == 0 || n > MAX_PATH) return; - lstrcatA(path, "wind_diag.log"); - FILE* f = nullptr; if (fopen_s(&f, path, "a") != 0 || !f) return; - va_list ap; va_start(ap, fmt); vfprintf(f, fmt, ap); va_end(ap); - fputc('\n', f); fclose(f); + char buf[1024]; + va_list ap; va_start(ap, fmt); _vsnprintf_s(buf, sizeof(buf), _TRUNCATE, fmt, ap); va_end(ap); + wind::Log(wind::LogLevel::Info, "diag", "%s", buf); } // Forward-declared so RunTick can re-register the hide-cursor hotkey on config hot-reload; @@ -909,18 +934,93 @@ static bool IdleNow(TickState& t) { return wind::IdleSleepOk(ii); } -// RunTick's own work time, for the zoom timeline (#310): two QPC reads per tick. +static double QpcMs(const TickState& t, long long a, long long b) { + return double(b - a) * 1000.0 / double(t.freq.QuadPart); +} + +// Hitch recorder (#361), tick start: close the previous tick's record (its work and post-tick +// flush are now known), open this one with the pacing wait the loop measured, and if the gap +// since the previous tick was a hitch, classify and log it. Logging is a queue push. +static void HitchBegin(TickState& t, long long now) { + auto& h = t.hitch; + const wind::TickRec prev = h.cur; + wind::TickRec cur{}; + cur.qpcStart = now; + cur.dtMs = h.havePrev ? (float)QpcMs(t, prev.qpcStart, now) : 0.0f; + cur.waitMs = h.pendWait; cur.wakeLateMs = h.pendLate; + cur.pulseGapMs = h.pendPulseGap; cur.pulseDelayMs = h.pendPulseDelay; + cur.flags = h.pendFlags | (t.wokeFromIdle ? wind::kTickWoke : 0u); + h.pendWait = h.pendLate = h.pendPulseGap = h.pendPulseDelay = -1; h.pendFlags = 0; + if (h.havePrev) { + const unsigned long long nowMs = GetTickCount64(); + const double frameMs = 1000.0 / (t.hz > 0 ? t.hz : 60); + const bool zoomed = prev.level > 1.0f || (prev.flags & (wind::kTickEnter | wind::kTickExit)); + if (zoomed && !(cur.flags & wind::kTickWoke)) h.minute.addTick(prev); + if (t.cfg.hitchLog && zoomed && wind::IsHitch(cur, frameMs, t.cfg.hitchThresholdPct)) { + const wind::HitchVerdict v = wind::ClassifyHitch(prev, cur, frameMs); + h.minute.addHitch(cur, v); + if (nowMs - h.lineWindowMs >= 1000) { h.lineWindowMs = nowMs; h.linesInWindow = 0; } + if (h.linesInWindow < 2) { // at most two lines a second; the rest are counted + ++h.linesInWindow; + float recent[8]; const int n = h.ring.size() < 8 ? h.ring.size() : 8; + for (int i = 0; i < n; ++i) recent[i] = h.ring.back(n - 1 - i).dtMs; + wind::Log(wind::LogLevel::Info, "hitch", "%s", + wind::FormatHitchLine(prev, cur, v, frameMs, recent, n, h.suppressed).c_str()); + h.suppressed = 0; + } else { + ++h.suppressed; + } + } + h.ring.push(prev); + if (h.minuteStartMs == 0) h.minuteStartMs = nowMs; + if (nowMs - h.minuteStartMs >= 60000) { + const std::string s = h.minute.format(); + if (t.cfg.hitchLog && !s.empty()) wind::Log(wind::LogLevel::Info, "hitch", "%s", s.c_str()); + h.minute.reset(); h.minuteStartMs = nowMs; + } + } + h.cur = cur; + h.havePrev = true; + wind::tl_tickSpans = h.cur.span; // SpanScope on this thread now times into this record +} + +// Tick end: work time, the thread's own CPU time inside it (wall minus CPU = off the CPU: waiting +// in a call or preempted), level, engine, zoom edge. +static void HitchEnd(TickState& t, long long now, double workMs, unsigned long long cycles, bool wasActive) { + auto& h = t.hitch; + auto& c = h.cur; + wind::tl_tickSpans = nullptr; + c.workMs = (float)workMs; + // QueryThreadCycleTime counts in TSC units: calibrate them against QPC over the first second. + if (h.cyclesPerMs > 0) { + c.cpuMs = (float)(double(cycles) / h.cyclesPerMs); + } else if (h.calQpc0 == 0) { + h.calQpc0 = now; h.calTsc0 = __rdtsc(); + } else if (QpcMs(t, h.calQpc0, now) >= 1000.0) { + h.cyclesPerMs = double(__rdtsc() - h.calTsc0) / QpcMs(t, h.calQpc0, now); + } + c.level = (float)t.prevLvl; + if (!wasActive && t.prevActive) c.flags |= wind::kTickEnter; + if (wasActive && !t.prevActive) c.flags |= wind::kTickExit; + if (dynamic_cast(t.model)) c.flags |= wind::kTickTransform; + else if (dynamic_cast(t.model)) c.flags |= wind::kTickRender; +} + +// RunTick's own work time, for the zoom timeline (#310) and the hitch recorder (#361). struct TickWorkTimer { - TickState& t; LARGE_INTEGER s; - explicit TickWorkTimer(TickState& x) : t(x) { QueryPerformanceCounter(&s); } + TickState& t; LARGE_INTEGER s; ULONG64 c0 = 0; bool wasActive; + explicit TickWorkTimer(TickState& x) : t(x), wasActive(x.prevActive) { + QueryPerformanceCounter(&s); + HitchBegin(t, s.QuadPart); + QueryThreadCycleTime(GetCurrentThread(), &c0); + } ~TickWorkTimer() { + ULONG64 c1 = 0; QueryThreadCycleTime(GetCurrentThread(), &c1); LARGE_INTEGER e; QueryPerformanceCounter(&e); t.lastTickWorkMs = double(e.QuadPart - s.QuadPart) * 1000.0 / double(t.freq.QuadPart); + HitchEnd(t, e.QuadPart, t.lastTickWorkMs, c1 - c0, wasActive); } }; -static double QpcMs(const TickState& t, long long a, long long b) { - return double(b - a) * 1000.0 / double(t.freq.QuadPart); -} // The next tick after a zoom-in/out: gather the composite and per-tick work, log when complete. static void ZoomTimelineStep(TickState& t, long long nowQpc) { auto& z = t.zt; @@ -1443,7 +1543,7 @@ static void RunTick(TickState& t) { } else { SetSystemCursorHidden(t, t.model, true); } - t.model->onActivate(); // grab a live frame, not a stale cached one + { wind::SpanScope span_(wind::kSpanActivate); t.model->onActivate(); } // grab a live frame, not a stale cached one } if (inspectEnter) { // Freeze the real cursor where it is; the look point (mapper center) starts there. @@ -1460,7 +1560,7 @@ static void RunTick(TickState& t) { RECT fz{ pt.x, pt.y, pt.x + 1, pt.y + 1 }; ClipCursor(&fz); SetSystemCursorHidden(t, t.model, true); // hide the real cursor; we draw the crosshair - t.model->onActivate(); + { wind::SpanScope span_(wind::kSpanActivate); t.model->onActivate(); } // Game-inspect (issue #144): if a mouselook game holds the mouse, the freeze alone is // not enough - its raw-input camera still receives every mickey. Steal foreground to // the invisible helper so the game stops getting input. Deferred via @@ -1754,7 +1854,7 @@ static void RunTick(TickState& t) { // call (it is also what fsGame below aliases). const bool trackEnabled = lvl > 1.001 && !panel && !inspect && !t.detector.locked() && !fsCover && (t.cfg.trackCaret != 0 || t.cfg.trackFocus != 0); - g_track.setActive(trackEnabled, t.cfg.trackCaret != 0, t.cfg.trackFocus != 0, t.cfg.trackLog != 0); + { wind::SpanScope span_(wind::kSpanTrack); g_track.setActive(trackEnabled, t.cfg.trackCaret != 0, t.cfg.trackFocus != 0, t.cfg.trackLog != 0); } if (t.cfg.trackLog) { // #326: why tracking is on or off, logged on every change const int bits = (lvl > 1.001 ? 1 : 0) | (panel ? 2 : 0) | (inspect ? 4 : 0) | (t.detector.locked() ? 8 : 0) | (fsCover ? 16 : 0); @@ -1802,7 +1902,7 @@ static void RunTick(TickState& t) { // or auto-repeat, is not typing (review #349). vi.keyAfterButton = wind::KeyAfterButton(g_input.lastTypingKeyDownMs(), t.lastButtonMs); vi.dtMs = dt * 1000.0; - vi.snap = g_track.snapshot(); + { wind::SpanScope span_(wind::kSpanTrack); vi.snap = g_track.snapshot(); } const wind::ViewOwner was = t.viewOwner.owner; const unsigned diagTargetSeqBefore = t.viewOwner.target.seq; const wind::ViewOwner owner = wind::StepViewOwner(t.viewOwner, vi); @@ -2031,7 +2131,7 @@ static void RunTick(TickState& t) { const bool fgIsStealer = fgTick && fgTick == g_focusStealer; // game-inspect helper holds fg if (want && want != t.model && wantSettled && !fgIsStealer) { if (t.restAfterReveal) { // rapid double-switch: settle the previous handover - t.restAfterReveal->setActive(false); + { wind::SpanScope span_(wind::kSpanActivate); t.restAfterReveal->setActive(false); } t.restAfterReveal = nullptr; t.restOverlapTicks = 0; UpdateColorFilter(t, true, RenderOverlayShown(t), nullptr); // colour follows what is visible @@ -2044,7 +2144,7 @@ static void RunTick(TickState& t) { // present (level > 1.001) and re-welds at the same point. if (dynamic_cast(t.model)) SetSystemCursorHidden(t, t.model, true); else t.transformExe = ExeNameOf(fgTick); // device-lost backstop attribution - t.model->onActivate(); + { wind::SpanScope span_(wind::kSpanActivate); t.model->onActivate(); } if (auto* rm = dynamic_cast(t.model)) { t.revealNeedsComposite = ForegroundCoversMonitor(t.mon); if (t.revealNeedsComposite) rm->primeReveal(); @@ -2062,7 +2162,7 @@ static void RunTick(TickState& t) { } else { // render -> transform: activate the transform THIS tick, keep the overlay up // for the same short overlap, then drop it. - t.model->setActive(true); + { wind::SpanScope span_(wind::kSpanActivate); t.model->setActive(true); } t.restAfterReveal = old; t.restOverlapTicks = TicksAtHz(3, t.hz); } @@ -2162,7 +2262,7 @@ static void RunTick(TickState& t) { } ex.suppressTransformWrite = hookWrite; ex.realPointer = panel; - UpdateColorFilter(t, lvl > 1.0, RenderOverlayShown(t), &ex); + { wind::SpanScope span_(wind::kSpanColor); UpdateColorFilter(t, lvl > 1.0, RenderOverlayShown(t), &ex); } // Serialize transform writes around an Inspect click's injected absolute move (issue #148 // TDR class): the injection and a transform write racing each other is the proven trigger. // The launch quiesce holds writes AND the weld for its whole window (see above). @@ -2260,7 +2360,7 @@ static void RunTick(TickState& t) { } if (doPresent) { LARGE_INTEGER zp0; if (t.zt.armed && t.zt.step == 0) QueryPerformanceCounter(&zp0); - t.model->present(r, lvl, t.cfg, t.mon, ex); // render+present (never blocks the ramp) + { wind::SpanScope span_(wind::kSpanPresent); t.model->present(r, lvl, t.cfg, t.mon, ex); } // render+present (never blocks the ramp) if (t.zt.armed && t.zt.step == 0 && t.zt.presentMs == 0) { LARGE_INTEGER zp1; QueryPerformanceCounter(&zp1); t.zt.presentMs = QpcMs(t, zp0.QuadPart, zp1.QuadPart); } @@ -2303,7 +2403,7 @@ static void RunTick(TickState& t) { // case still reveals within this same tick (the instant feel is kept); a loaded // GPU misses the budget and defers to the per-tick checks below. if (!t.revealNeedsComposite && rm->revealFrameDone(3.0)) { - rm->setActive(true); + { wind::SpanScope span_(wind::kSpanActivate); rm->setActive(true); } t.revealPending = 0; // Real-time overlap, same as the render -> transform path (issue #274): // raw ticks were right only at 144 Hz. @@ -2314,7 +2414,7 @@ static void RunTick(TickState& t) { const bool frameDone = rm->revealFrameDone(); const bool composited = !t.revealNeedsComposite || rm->frameCompositedSincePrime(); if ((frameDone && composited) || t.revealPending == 0) { - rm->setActive(true); + { wind::SpanScope span_(wind::kSpanActivate); rm->setActive(true); } wind::Log(wind::LogLevel::Info, "render", "deferred reveal: frameDone=%d composited=%d ticksLeft=%d", (int)frameDone, (int)composited, t.revealPending); @@ -2326,7 +2426,7 @@ static void RunTick(TickState& t) { } } else if (enterActive) { LARGE_INTEGER zs0; QueryPerformanceCounter(&zs0); - t.model->setActive(true); // transform: reveal immediately, no capture priming + { wind::SpanScope span_(wind::kSpanActivate); t.model->setActive(true); } // transform: reveal immediately, no capture priming if (t.zt.armed) { LARGE_INTEGER zs1; QueryPerformanceCounter(&zs1); t.zt.setActiveMs = QpcMs(t, zs0.QuadPart, zs1.QuadPart); if (auto* tm = dynamic_cast(t.model)) { @@ -2339,11 +2439,11 @@ static void RunTick(TickState& t) { // Handover overlap: the outgoing engine rests a few ticks after the incoming one is // live, so the crossover never composites a bare unmagnified frame (see instant switch). if (t.restAfterReveal && t.restOverlapTicks > 0 && --t.restOverlapTicks == 0) { - t.restAfterReveal->setActive(false); + { wind::SpanScope span_(wind::kSpanActivate); t.restAfterReveal->setActive(false); } t.restAfterReveal = nullptr; // The render overlay just left the screen: the DWM effect takes the colour back THIS // tick, not next tick's top-of-tick call (a one-frame unfiltered flash otherwise). - UpdateColorFilter(t, true, RenderOverlayShown(t), nullptr); + { wind::SpanScope span_(wind::kSpanColor); UpdateColorFilter(t, true, RenderOverlayShown(t), nullptr); } } // Execute the deferred game-inspect steal now that the reveal logic has read the true // foreground, and RE-assert it if the game pulled foreground back mid-inspect (some @@ -2423,13 +2523,13 @@ static void RunTick(TickState& t) { EndPanelFreeze(t); // #283: never leave the pointer pinned (review #284) // The caret/focus watcher is switched off only from the zoomed view block; a zoom-out that // snaps straight to 1.0 skipped it and left the watcher polling at 1x (#71). - g_track.setActive(false, t.cfg.trackCaret != 0, t.cfg.trackFocus != 0, t.cfg.trackLog != 0); + { wind::SpanScope span_(wind::kSpanTrack); g_track.setActive(false, t.cfg.trackCaret != 0, t.cfg.trackFocus != 0, t.cfg.trackLog != 0); } if (t.restAfterReveal) { t.restAfterReveal->setActive(false); t.restAfterReveal = nullptr; } // DWM effect back BEFORE the overlay hides: worst case one double-filtered frame, never a // bright unfiltered one (review 2026-09-30). - UpdateColorFilter(t, false, false, nullptr); + { wind::SpanScope span_(wind::kSpanColor); UpdateColorFilter(t, false, false, nullptr); } LARGE_INTEGER zo0; QueryPerformanceCounter(&zo0); - t.model->setActive(false); + { wind::SpanScope span_(wind::kSpanActivate); t.model->setActive(false); } if (t.cfg.zoomTrace) { LARGE_INTEGER zo1; QueryPerformanceCounter(&zo1); t.zt.outSetActiveMs = QpcMs(t, zo0.QuadPart, zo1.QuadPart); t.zt.outPending = true; @@ -3062,7 +3162,7 @@ int WINAPI wWinMain(HINSTANCE hInst, HINSTANCE, PWSTR, int) { } // Frame-pacing self-test: WIND_PACINGTEST runs the REAL present-paced render path at a forced - // zoom with a simulated pan for ~4 s and logs loop-interval stats to %TEMP%\wind_diag.log - + // zoom with a simulated pan for ~4 s and logs loop-interval stats as diag lines in wind-core.log - // to measure microstutter objectively (the normal loop needs the side button to zoom). Exits. if (GetEnvironmentVariableW(L"WIND_PACINGTEST", nullptr, 0) > 0) { // Pacing test drives the render path directly, so it only runs for the RenderModel. @@ -3188,6 +3288,7 @@ int WINAPI wWinMain(HINSTANCE hInst, HINSTANCE, PWSTR, int) { // Background CPU load must not stall a zoom (#334): this thread runs the tick loop. wind::RaiseTickThreadPriority(); wind::OptOutOfPowerThrottling(); + SetThreadDescription(GetCurrentThread(), L"Wind tick"); // names it in WPA and debuggers bool running = true; unsigned long long nextRecoverMs = 0; // device-lost recovery backoff gate (GetTickCount64) @@ -3281,8 +3382,27 @@ int WINAPI wWinMain(HINSTANCE hInst, HINSTANCE, PWSTR, int) { // only on genuine droop - at ~2/3 of the panel max rather than full rate, which // still keeps the weld tight without fighting the composite phase. const DWORD frameMs = ts.hz > 0 ? (DWORD)(1500 / ts.hz + 1) : 11; + LARGE_INTEGER wa; QueryPerformanceCounter(&wa); const DWORD w = WaitForSingleObject(g_compEvt, frameMs); + LARGE_INTEGER wb; QueryPerformanceCounter(&wb); wind::MarkComposite(); + { // Hitch recorder (#361): the wait, and who was late if it was long. + auto& h = ts.hitch; + h.pendFlags |= wind::kTickPacePulse; + h.pendWait = (float)QpcMs(ts, wa.QuadPart, wb.QuadPart); + const long long ps = g_pulseQpc.load(std::memory_order_acquire); + const long long pp = g_pulsePrevQpc.load(std::memory_order_relaxed); + const long long pc = g_pulseComposeQpc.load(std::memory_order_relaxed); + if (w == WAIT_OBJECT_0) { + // Signalled before the wait began: no wake latency to blame. + h.pendLate = ps > wa.QuadPart ? (float)QpcMs(ts, ps, wb.QuadPart) : 0.0f; + if (pp && ps > pp) h.pendPulseGap = (float)QpcMs(ts, pp, ps); + if (pc && ps >= pc) h.pendPulseDelay = (float)QpcMs(ts, pc, ps); + } else { + h.pendFlags |= wind::kTickPulseTimeout; + if (ps) h.pendPulseGap = (float)QpcMs(ts, ps, wb.QuadPart); // still no pulse + } + } // Telemetry: a droop episode is invisible in tick dt now that backfill exists, so // count it here. Logged once a second only when timeouts happened. static unsigned s_pulses = 0, s_timeouts = 0; @@ -3336,12 +3456,20 @@ int WINAPI wWinMain(HINSTANCE hInst, HINSTANCE, PWSTR, int) { // Anything else (WAIT_FAILED): fall back to the paced timer below, never spin. } if (!slept) { + LARGE_INTEGER wa; QueryPerformanceCounter(&wa); if (timer) { SetWaitableTimer(timer, &due, 0, nullptr, nullptr, FALSE); WaitForSingleObject(timer, INFINITE); } else { Sleep(1000 / pacedHz); } + LARGE_INTEGER wb; QueryPerformanceCounter(&wb); + // Hitch recorder (#361): the timer was due one period after it was armed. + auto& h = ts.hitch; + h.pendFlags |= wind::kTickPaceTimer; + h.pendWait = (float)QpcMs(ts, wa.QuadPart, wb.QuadPart); + const float late = h.pendWait - 1000.0f / (float)pacedHz; + h.pendLate = late > 0 ? late : 0.0f; } } @@ -3349,7 +3477,13 @@ int WINAPI wWinMain(HINSTANCE hInst, HINSTANCE, PWSTR, int) { if (dwmPaces) { + LARGE_INTEGER fa; QueryPerformanceCounter(&fa); DwmFlush(); // block until DWM's next composite -> frames align with it + { // Hitch recorder (#361): the flush belongs to the tick that just ran. + LARGE_INTEGER fb; QueryPerformanceCounter(&fb); + ts.hitch.cur.flushMs = (float)QpcMs(ts, fa.QuadPart, fb.QuadPart); + ts.hitch.cur.flags |= wind::kTickPaceFlush; + } wind::MarkComposite(); // frame boundary: the hook may write once more (issue #229) { // Composite timestamp: the late sprite refresh above measures its wait from here. LARGE_INTEGER qc; QueryPerformanceCounter(&qc); diff --git a/src/tick_span.h b/src/tick_span.h new file mode 100644 index 00000000..7d53d49b --- /dev/null +++ b/src/tick_span.h @@ -0,0 +1,41 @@ +// src/tick_span.h +// Time a part of the tick into the current TickRec (#361). The tick loop points tl_tickSpans at +// the record it is filling; anywhere on the tick thread can then wrap a call in +// wind::SpanScope s(wind::kSpanTxWrite); +// Two QPC reads when a record is live, one null check otherwise (other threads, or outside a +// tick), so it is safe in code shared with other threads. +#pragma once +#include +#include "hitch_record.h" + +namespace wind { + +inline thread_local float* tl_tickSpans = nullptr; + +inline double QpcToMs() { + static const double k = [] { + LARGE_INTEGER f; QueryPerformanceFrequency(&f); + return 1000.0 / double(f.QuadPart); + }(); + return k; +} + +class SpanScope { +public: + explicit SpanScope(int span) : span_(span), spans_(tl_tickSpans) { + if (spans_) QueryPerformanceCounter(&start_); + } + ~SpanScope() { + if (!spans_) return; + LARGE_INTEGER e; QueryPerformanceCounter(&e); + spans_[span_] += float(double(e.QuadPart - start_.QuadPart) * QpcToMs()); + } + SpanScope(const SpanScope&) = delete; + SpanScope& operator=(const SpanScope&) = delete; +private: + int span_; + float* spans_; + LARGE_INTEGER start_{}; +}; + +} // namespace wind diff --git a/src/transform_model.cpp b/src/transform_model.cpp index 9a37d86f..dd889a2d 100644 --- a/src/transform_model.cpp +++ b/src/transform_model.cpp @@ -371,6 +371,16 @@ void TransformModel::setActive(bool active) { return; } if (!magUp_) return; + // Teardown breakdown (#361): every step of the zoom-out timed and logged as one line, so a + // long zoom-out names its step instead of being one opaque total. + LARGE_INTEGER tf, t0; QueryPerformanceFrequency(&tf); QueryPerformanceCounter(&t0); + LARGE_INTEGER tPrev = t0; + double stepMs[9] = {}; + auto step = [&](int i) { + LARGE_INTEGER n; QueryPerformanceCounter(&n); + stepMs[i] = double(n.QuadPart - tPrev.QuadPart) * 1000.0 / double(tf.QuadPart); + tPrev = n; + }; // MPO buster: hide strictly AFTER the identity park below would be wrong - the park writes // identity while the game may still be mid-demotion-return; hiding HERE (before the park) // is also wrong for the same reason in reverse. Order chosen: park first (identity is a @@ -383,22 +393,27 @@ void TransformModel::setActive(bool active) { ShowSystemCursorMarshalled(TRUE); cursorHidden_ = false; } + step(0); // sprite hide + system cursor show // Unconditional (and idempotent): setActive(true) pre-blanks BEFORE the context exists, so // a session that never entered the draw branch (cursorVisibility=never, hide-hotkey) still // has blanked system cursors to give back even though cursorHidden_ never went true. if (blanker_) { blanker_->restore(); + step(1); // system cursor shapes restored // Windows repaints the pointer plane only on the next cursor EVENT, so a restored-but- // still pointer stays invisible until the hand moves (field-verified). A 1px nudge and // back generates that event invisibly. POINT np; if (GetCursorPos(&np)) { SetCursorPos(np.x + 1, np.y); SetCursorPos(np.x, np.y); } } + step(2); // pointer nudge edgeClipManage(false); // give the clip back before the session winds down + step(3); idleSinceMs_ = GetTickCount64(); // start the release countdown (idleTick) - wind::Log(wind::LogLevel::Info, "txsession", "session end maxLevel=%.2f", sessionMaxLevel_); + const double endMaxLevel = sessionMaxLevel_; if (traceOn_) traceDump(); sessionMaxLevel_ = 0.0; + step(4); // trace hand-off // Park at EXACT identity right here, at the end of the zoom-out. Returning DWM to identity // costs a ~150ms compositor stall no matter when it happens (measured), so pay it while the // user is still in zoom motion and expects movement - not 1.2s later while they are playing. @@ -408,6 +423,7 @@ void TransformModel::setActive(bool active) { // idle - see cfg.txRestLevel for why and what it costs. 1.0 is the shipped behaviour. host_.setTransform((float)restLevel_, 0, 0, 0, 0, false); QueryPerformanceCounter(&pb); + step(5); // identity park // The park applied 1.0 outside writeTransform, so sync the cached level: a stale lastLevel_ // here anchored the step cap's next session at the trailing zoom-out value (#219 bounce). lastLevel_ = restLevel_; lastRequestedLevel_ = restLevel_; @@ -418,13 +434,22 @@ void TransformModel::setActive(bool active) { wind::Log(wind::LogLevel::Info, "transform", "identity park took %.1fms", parkMs); RECT full{ 0, 0, mon_.w, mon_.h }; host_.setInputTransform(false, full, full); // input mapping back to identity at 1x + step(6); // Stomp-guard expectation (issue #217): the slot should now read DISABLED. Kept valid across // the idle so the next session's first tick catches a rect stranded meanwhile (e.g. a native // Magnifier killed while zoomed) and overwrites it immediately. ixExpectedValid_ = true; ixExpectedOn_ = false; pin_.hide(); + step(7); mpoGhost_.hide(); // after the identity park: re-promotion happens against a parked value + step(8); + const double total = double(tPrev.QuadPart - t0.QuadPart) * 1000.0 / double(tf.QuadPart); + wind::Log(wind::LogLevel::Info, "txsession", + "session end maxLevel=%.2f teardown=%.2fms (cursorShow=%.2f blankerRestore=%.2f nudge=%.2f " + "clip=%.2f trace=%.2f park=%.2f ix=%.2f pin=%.2f ghost=%.2f)", + endMaxLevel, total, stepMs[0], stepMs[1], stepMs[2], stepMs[3], stepMs[4], stepMs[5], + stepMs[6], stepMs[7], stepMs[8]); } void TransformModel::idleTick() { @@ -1109,9 +1134,26 @@ void TransformModel::shutdown() { ready_ = false; } -// Dump the per-tick trace. Diagnostic only: runs at session end, never on the tick path. +// Dump the per-tick trace (txTrace=1, diagnostic). Called at session end ON the tick thread, so it +// only copies the ring; a below-normal thread writes the file (#361: no disk I/O on the tick). void TransformModel::traceDump() { if (traceHead_ == 0) return; + const int n = traceHead_ < kTraceCap ? traceHead_ : kTraceCap; + const int start = traceHead_ < kTraceCap ? 0 : (traceHead_ % kTraceCap); + auto* rows = new std::vector(); + rows->reserve((size_t)n); + for (int i = 0; i < n; ++i) rows->push_back(traceBuf_[(start + i) % kTraceCap]); + traceHead_ = 0; + HANDLE th = CreateThread(nullptr, 0, [](LPVOID p) -> DWORD { + SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_BELOW_NORMAL); + std::unique_ptr> v(static_cast*>(p)); + WriteTraceCsv(*v); + return 0; + }, rows, 0, nullptr); + if (th) CloseHandle(th); else delete rows; +} + +void TransformModel::WriteTraceCsv(const std::vector& rows) { const std::wstring dir = wind::ResolveLogDir(); wchar_t path[MAX_PATH]; // Forward slash on purpose: Win32 file APIs accept it, and it keeps this string free @@ -1121,11 +1163,8 @@ void TransformModel::traceDump() { FILE* f = nullptr; if (_wfopen_s(&f, path, L"w") != 0 || !f) return; fprintf(f, "ms,dt,level,txX,offX,spriteX,spriteY,wrote,changed,ramping,warm\n"); - const int n = traceHead_ < kTraceCap ? traceHead_ : kTraceCap; - const int start = traceHead_ < kTraceCap ? 0 : (traceHead_ % kTraceCap); double prev = 0.0; - for (int i = 0; i < n; ++i) { - const TxTick& e = traceBuf_[(start + i) % kTraceCap]; + for (const TxTick& e : rows) { const double dt = prev > 0.0 ? (e.ms - prev) : 0.0; prev = e.ms; fprintf(f, "%.3f,%.3f,%.6f,%d,%d,%d,%d,%d,%d,%d,%d\n", @@ -1133,8 +1172,7 @@ void TransformModel::traceDump() { (int)e.wrote, (int)e.changed, (int)e.ramping, (int)e.warm); } fclose(f); - traceHead_ = 0; - wind::Log(wind::LogLevel::Info, "txtrace", "wrote %d ticks", n); + wind::Log(wind::LogLevel::Info, "txtrace", "wrote %d ticks", (int)rows.size()); } } // namespace wind diff --git a/src/transform_model.h b/src/transform_model.h index 34d8972f..8ce38df7 100644 --- a/src/transform_model.h +++ b/src/transform_model.h @@ -6,6 +6,7 @@ #include "cursor_sprite.h" #include "wobble_cage.h" #include +#include #include #include #include @@ -94,6 +95,7 @@ class TransformModel : public IMagnifierModel { int traceHead_ = 0; bool traceOn_ = false; void traceDump(); + static void WriteTraceCsv(const std::vector& rows); // background thread int zorderBand_; // sprite z-band (above the shell); needs UIAccess bool spriteBand16_ = false; // P2 experiment: band-16 SCREEN-space sprite bool cursorBandAuto_ = false; // issue #269: band 16 unless the snip overlay is up diff --git a/src/version.h b/src/version.h index addde5fd..75232d53 100644 --- a/src/version.h +++ b/src/version.h @@ -3,8 +3,8 @@ #pragma once #define WIND_VER_MAJOR 0 -#define WIND_VER_MINOR 22 -#define WIND_VER_PATCH 5 +#define WIND_VER_MINOR 23 +#define WIND_VER_PATCH 0 // String form for logs/snapshot/UI. Keep in sync with the numeric parts above. -#define WIND_VERSION_STR "0.22.5" +#define WIND_VERSION_STR "0.23.0" diff --git a/tests/test_hitch_record.cpp b/tests/test_hitch_record.cpp new file mode 100644 index 00000000..86b654aa --- /dev/null +++ b/tests/test_hitch_record.cpp @@ -0,0 +1,119 @@ +// tests/test_hitch_record.cpp - hitch classification and the hitch line (#361). +#include "doctest.h" +#include "../src/hitch_record.h" +#include +using namespace wind; + +static const double kFrame = 1000.0 / 144.0; // 6.94 ms + +static TickRec Normal() { + TickRec r; + r.dtMs = (float)kFrame; r.workMs = 0.8f; r.cpuMs = 0.7f; r.level = 2.0f; + r.flags = kTickTransform | kTickPacePulse; + r.waitMs = 6.0f; r.wakeLateMs = 0.1f; r.pulseGapMs = (float)kFrame; r.pulseDelayMs = 0.2f; + return r; +} + +TEST_CASE("IsHitch: threshold, and never on an idle wake") { + TickRec r = Normal(); + CHECK_FALSE(IsHitch(r, kFrame, 150)); + r.dtMs = 12.0f; + CHECK(IsHitch(r, kFrame, 150)); + CHECK_FALSE(IsHitch(r, kFrame, 200)); + r.flags |= kTickWoke; + CHECK_FALSE(IsHitch(r, kFrame, 150)); +} + +TEST_CASE("Classify: the tick thread woke late (scheduler)") { + TickRec prev = Normal(), cur = Normal(); + cur.dtMs = 38.0f; cur.waitMs = 37.0f; cur.wakeLateMs = 30.0f; + const HitchVerdict v = ClassifyHitch(prev, cur, kFrame); + CHECK(v.cause == HitchCause::LateWake); + CHECK(v.ms == doctest::Approx(30.0f)); +} + +TEST_CASE("Classify: DWM composed late vs the pulse thread ran late") { + TickRec prev = Normal(), cur = Normal(); + cur.dtMs = 30.0f; cur.waitMs = 29.0f; cur.wakeLateMs = 0.1f; + cur.pulseGapMs = 29.5f; cur.pulseDelayMs = 0.3f; // compose to signal was quick + CHECK(ClassifyHitch(prev, cur, kFrame).cause == HitchCause::CompositorLate); + cur.pulseDelayMs = 21.0f; // composed on time, signalled late + const HitchVerdict v = ClassifyHitch(prev, cur, kFrame); + CHECK(v.cause == HitchCause::PulseThreadLate); + CHECK(v.ms == doctest::Approx(21.0f)); +} + +TEST_CASE("Classify: blocked (off CPU) vs busy (on CPU) in the dominant span") { + TickRec prev = Normal(), cur = Normal(); + prev.workMs = 25.0f; prev.cpuMs = 1.0f; + prev.span[kSpanPresent] = 24.5f; prev.span[kSpanTxWrite] = 23.0f; + cur.dtMs = 31.0f; cur.waitMs = 5.0f; cur.wakeLateMs = 0.0f; + HitchVerdict v = ClassifyHitch(prev, cur, kFrame); + CHECK(v.cause == HitchCause::Blocked); + CHECK(v.span == kSpanTxWrite); // the specific span beats its container + prev.cpuMs = 24.0f; + v = ClassifyHitch(prev, cur, kFrame); + CHECK(v.cause == HitchCause::Busy); + prev.cpuMs = -1.0f; // not calibrated yet + CHECK(ClassifyHitch(prev, cur, kFrame).cause == HitchCause::SlowTick); +} + +TEST_CASE("Classify: long tick outside every span says untracked") { + TickRec prev = Normal(), cur = Normal(); + prev.workMs = 20.0f; prev.cpuMs = 19.0f; + prev.span[kSpanPresent] = 2.0f; + cur.dtMs = 26.0f; cur.waitMs = 5.0f; + const HitchVerdict v = ClassifyHitch(prev, cur, kFrame); + CHECK(v.cause == HitchCause::Busy); + CHECK(v.span == -1); + CHECK(FormatHitchLine(prev, cur, v, kFrame, nullptr, 0, 0).find("busy in untracked") != std::string::npos); +} + +TEST_CASE("Classify: post-tick DwmFlush and time between ticks") { + TickRec prev = Normal(), cur = Normal(); + prev.flushMs = 40.0f; prev.flags = kTickRender | kTickPaceFlush; + cur.flags = kTickRender; cur.dtMs = 41.0f; cur.waitMs = -1.0f; cur.wakeLateMs = -1.0f; + CHECK(ClassifyHitch(prev, cur, kFrame).cause == HitchCause::FlushWait); + prev.flushMs = 0.0f; cur.dtMs = 25.0f; // nothing measured explains it + const HitchVerdict v = ClassifyHitch(prev, cur, kFrame); + CHECK(v.cause == HitchCause::LoopOther); + CHECK(v.ms == doctest::Approx(25.0f - 0.8f)); +} + +TEST_CASE("FormatHitchLine carries the evidence") { + TickRec prev = Normal(), cur = Normal(); + prev.flags |= kTickExit; prev.workMs = 22.0f; prev.cpuMs = 1.5f; + prev.span[kSpanActivate] = 21.0f; + cur.dtMs = 28.0f; + const HitchVerdict v = ClassifyHitch(prev, cur, kFrame); + const float recent[3] = { 6.9f, 7.0f, 6.9f }; + const std::string s = FormatHitchLine(prev, cur, v, kFrame, recent, 3, 4); + CHECK(s.rfind("hitch dt=28.0ms", 0) == 0); + CHECK(s.find("cause=blocked in activate") != std::string::npos); + CHECK(s.find("zoom-out") != std::string::npos); + CHECK(s.find("pace=pulse") != std::string::npos); + CHECK(s.find("activate=21.0") != std::string::npos); + CHECK(s.find("recent dt 6.9 7.0 6.9") != std::string::npos); + CHECK(s.find("+4 more since last line") != std::string::npos); +} + +TEST_CASE("TickRing keeps the newest records") { + static TickRing ring; + for (int i = 0; i < TickRing::kCap + 10; ++i) { TickRec r; r.dtMs = (float)i; ring.push(r); } + CHECK(ring.size() == TickRing::kCap); + CHECK(ring.back(0).dtMs == doctest::Approx((float)(TickRing::kCap + 9))); + CHECK(ring.back(TickRing::kCap - 1).dtMs == doctest::Approx(10.0f)); +} + +TEST_CASE("HitchSummary rolls up a minute") { + HitchSummary m; + CHECK(m.format().empty()); + TickRec r = Normal(); + for (int i = 0; i < 100; ++i) m.addTick(r); + TickRec h = Normal(); h.dtMs = 40.0f; + m.addHitch(h, HitchVerdict{ HitchCause::LateWake, -1, 30.0f }); + const std::string s = m.format(); + CHECK(s.find("zoomed ticks=100 hitches=1") != std::string::npos); + CHECK(s.find("worst dt=40.0ms (late-wake)") != std::string::npos); + CHECK(s.find("late-wake=1") != std::string::npos); +} diff --git a/tests/test_log_queue.cpp b/tests/test_log_queue.cpp new file mode 100644 index 00000000..2e8d4aef --- /dev/null +++ b/tests/test_log_queue.cpp @@ -0,0 +1,69 @@ +// tests/test_log_queue.cpp - the non-blocking log queue (#361). +#include "doctest.h" +#include "../src/log_queue.h" +#include +#include +using namespace wind; + +TEST_CASE("LogQueue pops in push order") { + static LogQueue q; + for (int i = 0; i < 5; ++i) CHECK(q.push([i](int& v) { v = i; })); + for (int i = 0; i < 5; ++i) { + int got = -1; + CHECK(q.pop([&](const int& v) { got = v; })); + CHECK(got == i); + } + CHECK_FALSE(q.pop([](const int&) {})); +} + +TEST_CASE("LogQueue full drops instead of waiting") { + static LogQueue q; + for (int i = 0; i < 4; ++i) CHECK(q.push([i](int& v) { v = i; })); + bool called = false; + CHECK_FALSE(q.push([&](int&) { called = true; })); + CHECK_FALSE(called); // a full queue never touches the entry + int got = -1; + CHECK(q.pop([&](const int& v) { got = v; })); + CHECK(got == 0); + CHECK(q.push([](int& v) { v = 99; })); // one slot free again +} + +TEST_CASE("LogQueue ready() tracks the next entry across wraparound") { + static LogQueue q; + CHECK_FALSE(q.ready()); + for (int round = 0; round < 10; ++round) { + CHECK(q.push([round](int& v) { v = round; })); + CHECK(q.ready()); + int got = -1; + CHECK(q.pop([&](const int& v) { got = v; })); + CHECK(got == round); + CHECK_FALSE(q.ready()); + } +} + +TEST_CASE("LogQueue keeps every entry from concurrent producers") { + static LogQueue q; + const int kThreads = 4, kEach = 20000; + std::atomic pushed{0}, dropped{0}; + std::atomic done{false}; + long long sum = 0; int popped = 0; + std::thread consumer([&] { + for (;;) { + bool any = q.pop([&](const int& v) { sum += v; ++popped; }); + if (!any && done.load() && !q.ready()) break; + } + }); + std::vector producers; + for (int t = 0; t < kThreads; ++t) + producers.emplace_back([&] { + for (int i = 1; i <= kEach; ++i) { + if (q.push([i](int& v) { v = i; })) pushed++; else dropped++; + } + }); + for (auto& p : producers) p.join(); + done = true; + consumer.join(); + CHECK(popped == pushed.load()); + CHECK(pushed.load() + dropped.load() == kThreads * kEach); + if (dropped.load() == 0) CHECK(sum == (long long)kThreads * kEach * (kEach + 1) / 2); +} diff --git a/tests/test_logging.cpp b/tests/test_logging.cpp index e9a17058..e2990eb9 100644 --- a/tests/test_logging.cpp +++ b/tests/test_logging.cpp @@ -9,6 +9,13 @@ TEST_CASE("LogLevelName maps levels") { CHECK(std::string(LogLevelName(LogLevel::Error)) == "ERROR"); } +TEST_CASE("FormatLogLineEx adds the QPC ms and thread id after the timestamp") { + std::string line = FormatLogLineEx(1780215262137ULL, 123456.789, 4242, LogLevel::Warn, "render", "device lost"); + CHECK(line.find("Z +123456.789 t4242 WARN render device lost") != std::string::npos); + CHECK(line == FormatLogLine(1780215262137ULL, LogLevel::Warn, "render", "device lost") + .insert(24, " +123456.789 t4242")); +} + TEST_CASE("FormatLogLine renders ISO-8601 UTC ms + level + category + msg") { // 2026-05-31T08:14:22.137Z == 1780215262137 ms since epoch. std::string line = FormatLogLine(1780215262137ULL, LogLevel::Warn, "render", "device lost"); From d51df9e63eb6d42dda14b694b30cbb247e2f7da6 Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Sun, 4 Oct 2026 05:25:50 +0200 Subject: [PATCH 2/2] fix(diag): hitch line engine/level from the tick that ran; cursor and shape spans Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01KPUNAWcwghXdHCApcKKjSG --- src/cursor_blanker.cpp | 3 +++ src/cursor_sprite.cpp | 1 + src/hitch_record.cpp | 4 +++- src/hitch_record.h | 2 ++ src/transform_model.cpp | 2 ++ tests/test_hitch_record.cpp | 3 ++- 6 files changed, 13 insertions(+), 2 deletions(-) diff --git a/src/cursor_blanker.cpp b/src/cursor_blanker.cpp index 9f36f2bf..ce746d84 100644 --- a/src/cursor_blanker.cpp +++ b/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); diff --git a/src/cursor_sprite.cpp b/src/cursor_sprite.cpp index fb9dbc7b..39cb45f2 100644 --- a/src/cursor_sprite.cpp +++ b/src/cursor_sprite.cpp @@ -115,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; diff --git a/src/hitch_record.cpp b/src/hitch_record.cpp index a4b7c4b2..1c97a76e 100644 --- a/src/hitch_record.cpp +++ b/src/hitch_record.cpp @@ -13,6 +13,8 @@ const char* TickSpanName(int span) { case kSpanIx: return "ix"; case kSpanSprite: return "sprite"; case kSpanActivate: return "activate"; + case kSpanCursor: return "cursor"; + case kSpanShape: return "shape"; } return "?"; } @@ -102,7 +104,7 @@ std::string FormatHitchLine(const TickRec& prev, const TickRec& cur, const Hitch 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(cur.flags), PaceName(cur.flags), cur.level, + 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; diff --git a/src/hitch_record.h b/src/hitch_record.h index 2aefe177..6ff3d627 100644 --- a/src/hitch_record.h +++ b/src/hitch_record.h @@ -25,6 +25,8 @@ enum TickSpan : int { kSpanIx, // input-transform publish and read-back kSpanSprite, // cursor sprite window moves and show/hide kSpanActivate, // zoom-in / zoom-out session start and end + kSpanCursor, // system cursor set swaps (blank / restore) and show/hide + kSpanShape, // reading and rendering the cursor shape for the sprite kSpanCount }; const char* TickSpanName(int span); diff --git a/src/transform_model.cpp b/src/transform_model.cpp index dd889a2d..fbcb8bb9 100644 --- a/src/transform_model.cpp +++ b/src/transform_model.cpp @@ -7,6 +7,7 @@ #include "logging.h" #include "sprite_layer.h" // PickSpriteLayer (pure, tested): issue #269 #include "config_path.h" // ResolveLogDir +#include "tick_span.h" // per-tick spans (#361) #include #include #include @@ -26,6 +27,7 @@ namespace wind { // with failures counted so the proving ground can see a hide that did not take. static std::atomic g_showCursorFails{0}; static bool ShowSystemCursorMarshalled(BOOL show) { + wind::SpanScope span(wind::kSpanCursor); const bool ok = wind::MagThreadInvoke([show]() -> bool { return MagShowSystemCursor(show) != FALSE; }); diff --git a/tests/test_hitch_record.cpp b/tests/test_hitch_record.cpp index 86b654aa..e6a22904 100644 --- a/tests/test_hitch_record.cpp +++ b/tests/test_hitch_record.cpp @@ -85,13 +85,14 @@ TEST_CASE("FormatHitchLine carries the evidence") { prev.flags |= kTickExit; prev.workMs = 22.0f; prev.cpuMs = 1.5f; prev.span[kSpanActivate] = 21.0f; cur.dtMs = 28.0f; + cur.flags = kTickPacePulse; cur.level = 1.0f; // the new tick has not run: no engine, no level const HitchVerdict v = ClassifyHitch(prev, cur, kFrame); const float recent[3] = { 6.9f, 7.0f, 6.9f }; const std::string s = FormatHitchLine(prev, cur, v, kFrame, recent, 3, 4); CHECK(s.rfind("hitch dt=28.0ms", 0) == 0); CHECK(s.find("cause=blocked in activate") != std::string::npos); CHECK(s.find("zoom-out") != std::string::npos); - CHECK(s.find("pace=pulse") != std::string::npos); + CHECK(s.find("eng=transform pace=pulse lvl=2.00") != std::string::npos); // from the tick that ran CHECK(s.find("activate=21.0") != std::string::npos); CHECK(s.find("recent dt 6.9 7.0 6.9") != std::string::npos); CHECK(s.find("+4 more since last line") != std::string::npos);