From e2f158fea7f346fb5329a4dbe1a86fee56b7b833 Mon Sep 17 00:00:00 2001 From: "Gordon Lam (SH)" Date: Wed, 15 Jul 2026 11:18:01 +0800 Subject: [PATCH] Emit real elapsed time from SlowOperation telemetry (single event) Follow-up to #40269, which introduced SlowOperationWatcher. As noted in that PR's review, when the threshold timer fires we learn only that an operation was slow, not *how* slow -- it could have finished at 10.1 s or still be stuck at 60 s -- and "logging the elapsed time at scope exit could be the most useful" follow-up. This adds that, while keeping the watcher a passive, telemetry-only observer that emits **at most one** event. Behavior (exactly one of): - Fast path: the operation finishes under SlowThreshold (10 s default) -- the common case. Nothing is emitted. - Slow completion: it finishes but took >= SlowThreshold. On scope exit (destructor / Reset()) one `timedOut=false` SlowOperation event is emitted with the real `elapsedMs` since construction -- the authoritative total duration. - Hang backstop: it is still running at MaxDuration (15 min default). A single-shot timer fires once and emits one `timedOut=true` event (elapsedMs ~= MaxDuration), then stops -- so an operation that never returns (e.g. an HCS wait that blocks INFINITE, where the destructor never runs) is still reported exactly once instead of being invisible. It never repeats. So SlowThreshold is the "slow enough to report at completion" filter and MaxDuration is the "give up waiting and report the hang, once" deadline. m_reported (atomic) guarantees at most one event across the timer callback, Reset(), and the destructor. The event schema gains `elapsedMs` (Int64) and `completed` (Boolean); the existing `name`, `thresholdMs`, `file`, `function`, `line` fields are unchanged (additive, backward compatible). Compatibility / safety: - The two new constructor parameters (MaxDuration, OnSlow) are defaulted, so every existing call site compiles and behaves identically; the fast path emits nothing. - Only WSL_LOG_TELEMETRY is emitted (which also lands in ETL) -- no second log. - The threadpool callback dereferences the watcher, but Finish() resets the timer (cancel + drain in-flight callback) before any member is destroyed, so there is no use-after-free. The emission path is fully noexcept + CATCH_LOG guarded, so a telemetry failure can never crash or alter the watched operation. - No call sites are added or moved; the change is confined to the watcher class. Tests: adds test/windows/SlowOperationWatcherUnitTests.cpp (TAEF) covering the fast path, default-constructed fast path, slow completion (one completed=true with real elapsed), Reset() at-most-once, and the hang backstop (one completed=false at max, no second event on scope exit) -- via an injected recording sink. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 8f7fab85-2f28-4344-9454-b76e8d2cc4d4 --- src/windows/common/SlowOperationWatcher.cpp | 125 ++++++-- src/windows/common/SlowOperationWatcher.h | 124 ++++++-- test/windows/CMakeLists.txt | 1 + .../windows/SlowOperationWatcherUnitTests.cpp | 269 ++++++++++++++++++ 4 files changed, 481 insertions(+), 38 deletions(-) create mode 100644 test/windows/SlowOperationWatcherUnitTests.cpp diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp index e08a515919..52265f16ce 100644 --- a/src/windows/common/SlowOperationWatcher.cpp +++ b/src/windows/common/SlowOperationWatcher.cpp @@ -8,12 +8,23 @@ Module Name: Abstract: - See header for contract. A single-shot threadpool timer is armed for SlowThreshold - in the constructor. If it fires, the callback emits one `SlowOperation` telemetry - event with the phase name and captured std::source_location. The timer is owned by - wil::unique_threadpool_timer, whose destroyer cancels pending callbacks and blocks - for any in-flight callback before closing, so OnTimerFired cannot dereference - `*this` after destruction. + See header for contract. A single-shot threadpool timer is armed for MaxDuration in + the constructor. Emission is at most one event, guarded by m_reported (atomic): + + - If the operation finishes first (destructor or Reset()), Finish() cancels+drains + the timer and, if the elapsed time is at least SlowThreshold, emits one + timedOut=false event with the real elapsed time. Under-threshold => silent. + - If the operation is still running at MaxDuration, the timer fires once and emits + one timedOut=true event (elapsed ~= MaxDuration) as the hang backstop, then does + nothing more; a later scope exit sees m_reported set and stays silent. + + timedOut is a finished-vs-hung flag, NOT success-vs-failure: the watcher is a pure + duration timer with no visibility into the operation's result, so a scope that exits + by throwing is still reported timedOut=false. + + The timer is owned by wil::unique_threadpool_timer, whose destroyer cancels the pending + callback and blocks for any in-flight callback before closing, so OnTimerFired cannot + dereference `*this` after destruction and m_reported is stable once the timer is drained. --*/ @@ -44,33 +55,115 @@ static_assert(Basename("C:\\src\\test.cpp") == "test.cpp"); static_assert(Basename("no_separator.cpp") == "no_separator.cpp"); } // namespace -SlowOperationWatcher::SlowOperationWatcher(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location) : - m_name(Name), m_slowThreshold(SlowThreshold), m_location(Location) +// clang-format off +SlowOperationWatcher::SlowOperationWatcher( + _In_z_ const char* Name, + Duration SlowThreshold, + Duration MaxDuration, + Sink OnSlow, + std::source_location Location) noexcept : + // clang-format on + m_name(Name), + m_slowThreshold(SlowThreshold), + m_maxDuration(MaxDuration), + m_location(Location), + m_start(std::chrono::steady_clock::now()), + m_sink(OnSlow), + m_reported(false) { + // Internal invariants (all call sites pass compile-time constants, so a violation is a + // programming error): a real sink, a positive threshold, and MaxDuration >= SlowThreshold. + // The last one guarantees the hang backstop can never fire before the slow threshold, so a + // timedOut=true record is never emitted for an operation that isn't yet "slow". + WI_ASSERT(m_sink != nullptr); + WI_ASSERT(m_slowThreshold.count() > 0); + WI_ASSERT(m_maxDuration >= m_slowThreshold); + + // Best-effort: this is a passive telemetry observer, so timer allocation failure must not + // propagate into (and abort) the watched operation. If the timer can't be created we simply + // run without the hang backstop -- the completion path (Finish() on scope exit / Reset()) + // still emits a timedOut=false record for a slow operation, since it does not depend on the timer. m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); - THROW_IF_NULL_ALLOC(m_timer.get()); + if (m_timer) + { + // Single-shot: fire once at MaxDuration as the hang backstop. If the operation finishes + // first, Finish() cancels this before it fires. The due time is a 64-bit FILETIME, so it + // represents any realistic MaxDuration without truncation; period 0 = one-shot. + FILETIME due = RelativeFileTime(m_maxDuration); + SetThreadpoolTimer(m_timer.get(), &due, 0, 0); + } +} - FILETIME due = RelativeFileTime(m_slowThreshold); - SetThreadpoolTimer(m_timer.get(), &due, 0, 0); +SlowOperationWatcher::~SlowOperationWatcher() noexcept +{ + Finish(); } void SlowOperationWatcher::Reset() noexcept { + Finish(); +} + +void SlowOperationWatcher::Finish() noexcept +{ + // Cancel the backstop timer and drain any in-flight callback. After this returns no + // OnTimerFired can run, so m_reported is stable. m_timer.reset(); + + // The FIRST Finish() -- whether Reset() or the destructor -- permanently claims the + // single report and decides emit-or-not from the elapsed time AT THIS MOMENT. This is + // what makes Reset() an authoritative "operation ended here" marker: if the operation + // was fast (< threshold) at Reset(), we still claim m_reported so the later destructor + // cannot re-evaluate a larger elapsed (including post-Reset work) and emit a bogus + // slow record. If it was slow, we emit exactly one timedOut=false record with the real + // duration here, and the destructor is then a no-op. exchange also races safely against + // the timer callback (which claims m_reported the same way). + if (!m_reported.exchange(true)) + { + const auto elapsed = Elapsed(); + if (elapsed >= m_slowThreshold) + { + Emit(false, elapsed); + } + } +} + +SlowOperationWatcher::Duration SlowOperationWatcher::Elapsed() const noexcept +{ + return std::chrono::duration_cast(std::chrono::steady_clock::now() - m_start); +} + +void SlowOperationWatcher::Emit(bool TimedOut, Duration Elapsed) noexcept +{ + m_sink(Event{m_name, m_slowThreshold, Elapsed, TimedOut, m_location}); } void CALLBACK SlowOperationWatcher::OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept try { + // The single-shot timer reached MaxDuration while the operation is still running: emit the + // hang backstop record once (timedOut=true, elapsed ~= MaxDuration) and stop. If Finish() + // already reported (a race with a near-simultaneous scope exit), exchange keeps this a no-op. auto* self = static_cast(Context); + if (!self->m_reported.exchange(true)) + { + self->Emit(true, self->Elapsed()); + } +} +CATCH_LOG() +void SlowOperationWatcher::EmitTelemetry(const Event& Record) noexcept +try +{ WSL_LOG_TELEMETRY( "SlowOperation", PDT_ProductAndServicePerformance, - TraceLoggingValue(self->m_name, "name"), - TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs"), - TraceLoggingValue(Basename(self->m_location.file_name()).data(), "file"), - TraceLoggingValue(self->m_location.function_name(), "function"), - TraceLoggingUInt32(self->m_location.line(), "line")); + TraceLoggingValue(Record.Name, "name"), + TraceLoggingInt64(Record.Threshold.count(), "thresholdMs"), + TraceLoggingInt64(Record.Elapsed.count(), "elapsedMs"), + TraceLoggingBool(Record.TimedOut, "timedOut"), + TraceLoggingValue(Basename(Record.Location.file_name()).data(), "file"), + TraceLoggingValue(Record.Location.function_name(), "function"), + TraceLoggingUInt32(Record.Location.line(), "line")); } CATCH_LOG() diff --git a/src/windows/common/SlowOperationWatcher.h b/src/windows/common/SlowOperationWatcher.h index 55b86c637b..76ecb17c90 100644 --- a/src/windows/common/SlowOperationWatcher.h +++ b/src/windows/common/SlowOperationWatcher.h @@ -8,14 +8,36 @@ Module Name: Abstract: - RAII guard that watches a scoped operation. A threadpool timer is armed in the - constructor for `SlowThreshold` (10 s default). On the fast path (scope exits - before the threshold) the watcher's destructor cancels and drains the timer and - nothing is emitted. If the threshold is reached first -- including while the - scope is still running or hung indefinitely -- the timer callback fires once, - emitting a single `SlowOperation` telemetry event carrying the phase name and - the call site captured via std::source_location, so the backend can attribute - where time is spent. + RAII guard that times a scoped operation and emits **at most one** `SlowOperation` + telemetry event. There are exactly three outcomes: + + 1. The operation finishes in under `SlowThreshold` (10 s default) -- the common, + healthy case. Nothing is emitted. + 2. The operation finishes but took at least `SlowThreshold`. On the watched operation's + end -- the destructor, or the earlier Reset() call site -- one `timedOut=false` event + is emitted carrying the real `elapsedMs` measured from construction to that point (the + full scope lifetime for the destructor case; up to the Reset() call when Reset() is + used to disarm early). Note this says nothing about whether the operation *succeeded*: + a scope that exits by throwing is still reported here (the watcher is a pure duration + timer and has no visibility into the operation's result). + 3. The operation is still running after `MaxDuration` (15 min default) -- i.e. it is + hung or pathologically slow. A single-shot timer fires once at `MaxDuration` and + emits one `timedOut=true` event with `elapsedMs ~= MaxDuration`, then stops. + This is the backstop for an operation that never returns (e.g. an HCS wait that + blocks INFINITE, where the destructor never runs). It never repeats, and once it + has fired the later scope exit does not emit a second event. This backstop is + best-effort: if the threadpool timer cannot be created at construction, it is + silently skipped (the watcher never affects the watched operation), so a hang + may go unreported in that rare case. MaxDuration is the time a hang stays silent, + so the default sits well above the longest legitimate operation timeout (the + service's hard timeouts are on the order of minutes) to avoid misreporting a + slow-but-valid operation, while still surfacing a true hang. + + So `SlowThreshold` is the "slow enough to be worth reporting" filter applied at + completion, and `MaxDuration` is the "give up waiting and report the hang" deadline. + Every event carries the phase name and the call site (std::source_location). The + watcher is a passive observer: it never affects the operation it measures, and a + failure in the telemetry path can never crash or slow the watched code. Usage: @@ -37,31 +59,68 @@ Module Name: #include #include +#include #include #include class SlowOperationWatcher { public: - // Name is restricted to a string-literal reference (const char (&)[N]) to guarantee - // static storage duration: the raw pointer is dereferenced later from a threadpool - // callback, so accepting a `const char*` would make UAF via a temporary (e.g. - // std::string::c_str()) easy. Keep Name a short CamelCase phase identifier that the - // backend query can switch on (e.g. "WaitForMiniInitConnect"). + // Alias for the millisecond durations used throughout the class (threshold, max, elapsed). + using Duration = std::chrono::milliseconds; + + // Contents of one SlowOperation telemetry record. Exposed so tests can observe + // emissions through a custom sink without standing up an ETW listener. + struct Event + { + const char* Name; // phase identifier; must outlive the watcher + Duration Threshold; // configured slow threshold + Duration Elapsed; // real time since construction + bool TimedOut; // false: the scope finished (slow); Elapsed is the total. + // true: still running at MaxDuration (hang backstop). + // NOT a success/failure flag -- the watcher cannot know + // the operation's result; a throwing scope is TimedOut=false. + // By value, not a reference: a diagnostic sink may copy the Event and read it after + // the watcher is destroyed, which would dangle a reference. std::source_location is + // cheap to copy, so keep Event self-contained. + std::source_location Location; + }; + + // Receives the (at most one) SlowOperation record. Must be noexcept and must not block: + // it is invoked either from the MaxDuration threadpool callback (timedOut=true) or from + // Reset()/the destructor (timedOut=false). The default writes the telemetry event. + using Sink = void (*)(const Event&) noexcept; + + // Name is taken as a char-array reference (const char (&)[N]) rather than a const char* + // to force callers to pass an array and block the easy UAF of a temporary's pointer + // (e.g. std::string::c_str()): the raw pointer is dereferenced later from a threadpool + // callback, so the pointed-to storage must outlive the watcher and any pending callback. + // The array type does not by itself guarantee static storage -- a non-static array would + // also compile -- so in practice always pass a string literal. Keep Name a short CamelCase + // phase identifier that the backend query can switch on (e.g. "WaitForMiniInitConnect"). + // SlowThreshold is the "slow enough to report at completion" filter; MaxDuration is the + // "report the hang and stop" deadline. OnSlow defaults to the telemetry emitter; tests + // inject a recording sink. template explicit SlowOperationWatcher( const char (&Name)[N], - std::chrono::milliseconds SlowThreshold = std::chrono::seconds{10}, - std::source_location Location = std::source_location::current()) : - SlowOperationWatcher(static_cast(Name), SlowThreshold, Location) + Duration SlowThreshold = std::chrono::seconds{10}, + Duration MaxDuration = std::chrono::minutes{15}, + Sink OnSlow = &EmitTelemetry, + std::source_location Location = std::source_location::current()) noexcept : + SlowOperationWatcher(static_cast(Name), SlowThreshold, MaxDuration, OnSlow, Location) { } - ~SlowOperationWatcher() noexcept = default; + // On destruction, emits the timedOut=false record if the operation was slow (>= threshold) + // and the hang backstop hasn't already reported. + ~SlowOperationWatcher() noexcept; - // Disarm the watcher early. After Reset() returns, the threshold callback is - // guaranteed not to fire. Relies on wil::unique_threadpool_timer's destroyer to - // cancel pending callbacks and drain any in-flight one. + // Disarm the watcher early (equivalent to the destructor, but at an explicit point). Cancels + // and drains the MaxDuration timer, then -- if the operation took at least SlowThreshold and + // the hang backstop hasn't already fired -- emits one timedOut=false record with the real + // elapsed time. The fast path (under threshold) stays silent. Emits at most once across + // Reset() + the destructor. void Reset() noexcept; SlowOperationWatcher(const SlowOperationWatcher&) = delete; @@ -70,12 +129,33 @@ class SlowOperationWatcher SlowOperationWatcher& operator=(SlowOperationWatcher&&) = delete; private: - explicit SlowOperationWatcher(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location); + // clang-format off + explicit SlowOperationWatcher( + _In_z_ const char* Name, + Duration SlowThreshold, + Duration MaxDuration, + Sink OnSlow, + std::source_location Location) noexcept; + // clang-format on static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept; + // Default sink: writes the SlowOperation telemetry event. + static void EmitTelemetry(const Event& Record) noexcept; + + Duration Elapsed() const noexcept; + void Emit(bool TimedOut, Duration Elapsed) noexcept; + + // Cancel + drain the timer, then emit the timedOut=false record if the operation was slow + // and the hang backstop hasn't already reported. + void Finish() noexcept; + const char* const m_name; - const std::chrono::milliseconds m_slowThreshold; + const Duration m_slowThreshold; + const Duration m_maxDuration; const std::source_location m_location; + const std::chrono::steady_clock::time_point m_start; + const Sink m_sink; + std::atomic m_reported; // set once the single event has been emitted (by either path) wil::unique_threadpool_timer m_timer; }; diff --git a/test/windows/CMakeLists.txt b/test/windows/CMakeLists.txt index 54831cd629..f6ac80fbfa 100644 --- a/test/windows/CMakeLists.txt +++ b/test/windows/CMakeLists.txt @@ -10,6 +10,7 @@ set(SOURCES PolicyTests.cpp InstallerTests.cpp WSLCTests.cpp + SlowOperationWatcherUnitTests.cpp WslcSdkTests.cpp WslcSdkWinRtTests.cpp WindowsUpdateTests.cpp) diff --git a/test/windows/SlowOperationWatcherUnitTests.cpp b/test/windows/SlowOperationWatcherUnitTests.cpp new file mode 100644 index 0000000000..2e5760da06 --- /dev/null +++ b/test/windows/SlowOperationWatcherUnitTests.cpp @@ -0,0 +1,269 @@ +/*++ + +Copyright (c) Microsoft. All rights reserved. + +Module Name: + + SlowOperationWatcherUnitTests.cpp + +Abstract: + + Unit tests for SlowOperationWatcher. These exercise the emission logic through an + injected recording sink, so no ETW listener or running distro is required. The + watcher emits AT MOST ONE event: + + - Fast path (finishes under SlowThreshold): nothing is emitted. + - Slow completion (finishes at >= SlowThreshold, before MaxDuration): exactly one + timedOut=false event with the real elapsed time. + - Hang (still running at MaxDuration): exactly one timedOut=true event with + elapsed ~= MaxDuration, and no second event when the scope later exits. + - Reset() behaves like the destructor and never double-emits. + +--*/ + +#include "precomp.h" +#include "Common.h" + +#include +#include +#include + +namespace SlowOperationWatcherUnitTests { + +namespace { + + using namespace std::chrono_literals; + + struct RecordedEvent + { + std::string Name; + std::chrono::milliseconds Threshold; + std::chrono::milliseconds Elapsed; + bool TimedOut; + unsigned Line; + }; + + // The sink is a plain function pointer (no captures), so recorded events land in this + // file-scope recorder. TAEF runs the methods of a class serially, and each test resets + // the recorder up front, so there is no cross-test interference. + struct Recorder + { + std::mutex Lock; + std::vector Events; + + void Clear() + { + std::scoped_lock lock{Lock}; + Events.clear(); + } + + std::vector Snapshot() + { + std::scoped_lock lock{Lock}; + return Events; + } + }; + + Recorder g_recorder; + + void RecordSink(const SlowOperationWatcher::Event& e) noexcept + try + { + std::scoped_lock lock{g_recorder.Lock}; + g_recorder.Events.push_back(RecordedEvent{e.Name, e.Threshold, e.Elapsed, e.TimedOut, e.Location.line()}); + } + CATCH_LOG() + + // Poll until the recorder holds at least Count events or the deadline passes. The + // MaxDuration callback runs on a threadpool thread, so a short bounded wait avoids racing + // it without making the test sleep for a fixed, flaky duration. + bool WaitForEvents(size_t Count, std::chrono::milliseconds Timeout) + { + const auto deadline = std::chrono::steady_clock::now() + Timeout; + while (std::chrono::steady_clock::now() < deadline) + { + { + std::scoped_lock lock{g_recorder.Lock}; + if (g_recorder.Events.size() >= Count) + { + return true; + } + } + + std::this_thread::sleep_for(5ms); + } + + std::scoped_lock lock{g_recorder.Lock}; + return g_recorder.Events.size() >= Count; + } + + // A MaxDuration far larger than the test window so the hang backstop never fires while + // exercising the completion paths. + constexpr auto c_noHang = 30s; + +} // namespace + +class SlowOperationWatcherUnitTests +{ + WSL_TEST_CLASS(SlowOperationWatcherUnitTests) + + TEST_CLASS_SETUP(TestClassSetup) + { + return true; + } + + TEST_CLASS_CLEANUP(TestClassCleanup) + { + return true; + } + + TEST_METHOD_SETUP(MethodSetup) + { + g_recorder.Clear(); + return true; + } + + // An operation that finishes comfortably under the threshold emits nothing. + TEST_METHOD(FastPathEmitsNothing) + { + { + SlowOperationWatcher watcher{"FastPath", 30s, c_noHang, &RecordSink}; + } + + VERIFY_ARE_EQUAL(g_recorder.Snapshot().size(), static_cast(0)); + } + + // The default threshold/max fast path stays silent, asserted through the injected sink. + // Also compile-checks the single-argument call-site form (all timing params defaulted), + // which is how every real call site constructs the watcher. + TEST_METHOD(DefaultConstructionFastPathEmitsNothing) + { + { + // Injected sink with the DEFAULT threshold (10 s) and max (15 min): a scope that + // exits immediately is well under threshold, so nothing must be recorded. This is + // the assertion the production-sink single-arg form below cannot make (it writes to + // ETW, not g_recorder). + SlowOperationWatcher watcher{"Defaults", std::chrono::seconds{10}, std::chrono::minutes{15}, &RecordSink}; + } + VERIFY_ARE_EQUAL(g_recorder.Snapshot().size(), static_cast(0)); + + { + // Compile/behavior smoke test of the single-argument overload used by call sites + // (defaults the threshold, max, and the production telemetry sink). Fast path, so + // it emits nothing and touches no ETW; nothing new should reach the recorder. + SlowOperationWatcher watcher{"Defaults"}; + } + VERIFY_ARE_EQUAL(g_recorder.Snapshot().size(), static_cast(0)); + } + + // Reset() before the threshold disarms the watcher permanently: it stays silent at + // Reset(), AND -- critically -- the destructor must not later re-evaluate a larger + // elapsed (including work done after Reset()) and emit. Reset() is an authoritative + // "operation ended here" marker, so post-Reset work must never be attributed to it. + TEST_METHOD(ResetBeforeThresholdEmitsNothing) + { + // A large threshold relative to scheduling jitter: Reset() fires ~immediately after + // construction, so the elapsed-at-Reset can only cross 300ms if the thread stalls for + // >300ms before the very next statement, which is not realistic even on a busy CI box. + constexpr auto threshold = 300ms; + { + SlowOperationWatcher watcher{"ResetFast", threshold, c_noHang, &RecordSink}; + + // The watched operation finished quickly (under threshold) -> Reset() here. + watcher.Reset(); + VERIFY_ARE_EQUAL(g_recorder.Snapshot().size(), static_cast(0)); + + // Simulate slow, unrelated work AFTER Reset() that pushes total elapsed past the + // threshold. The destructor at scope exit must still emit nothing (Reset() already + // claimed the single report), which is the property under test. + std::this_thread::sleep_for(400ms); + } + + VERIFY_ARE_EQUAL(g_recorder.Snapshot().size(), static_cast(0)); + } + + // A slow operation that finishes before MaxDuration emits exactly ONE timedOut=false + // record with the real elapsed time (>= threshold, and reflecting the extra time). + TEST_METHOD(SlowCompletionEmitsOneRecord) + { + constexpr auto threshold = 50ms; + { + SlowOperationWatcher watcher{"SlowPhase", threshold, c_noHang, &RecordSink}; + + // Stay alive well past the threshold, but far below MaxDuration. + std::this_thread::sleep_for(200ms); + } + + const auto events = g_recorder.Snapshot(); + VERIFY_ARE_EQUAL(events.size(), static_cast(1)); + + const auto& record = events[0]; + VERIFY_IS_FALSE(record.TimedOut); + VERIFY_ARE_EQUAL(record.Name, std::string{"SlowPhase"}); + VERIFY_ARE_EQUAL(record.Threshold, threshold); + + // The record carries the real elapsed time, not just the threshold. + VERIFY_IS_TRUE(record.Elapsed >= threshold); + VERIFY_IS_TRUE(record.Elapsed >= 150ms); + + // source_location survived being copied into the Event (by value, no dangling ref). + VERIFY_IS_TRUE(record.Line != 0); + } + + // Reset() after the threshold emits the one timedOut=false record, and the destructor + // that follows must not emit a second one (at-most-once via m_reported.exchange). + TEST_METHOD(ResetAfterThresholdEmitsOnce) + { + constexpr auto threshold = 50ms; + { + SlowOperationWatcher watcher{"ResetSlow", threshold, c_noHang, &RecordSink}; + + std::this_thread::sleep_for(150ms); + watcher.Reset(); + + const auto afterReset = g_recorder.Snapshot(); + VERIFY_ARE_EQUAL(afterReset.size(), static_cast(1)); + VERIFY_IS_FALSE(afterReset[0].TimedOut); + VERIFY_IS_TRUE(afterReset[0].Elapsed >= threshold); + } + + // Destruction after Reset() must not produce a second record. + VERIFY_ARE_EQUAL(g_recorder.Snapshot().size(), static_cast(1)); + } + + // An operation still running at MaxDuration emits exactly ONE timedOut=true record + // (the hang backstop) with elapsed ~= MaxDuration, and NO second record when the scope + // finally exits well past the cap. This is the "report at max and stop" behavior. + TEST_METHOD(HangEmitsOnceAtMaxThenStops) + { + constexpr auto threshold = 40ms; + constexpr auto maxDuration = 120ms; + { + SlowOperationWatcher watcher{"Hang", threshold, maxDuration, &RecordSink}; + + // Wait for the backstop to fire at ~maxDuration. + VERIFY_IS_TRUE(WaitForEvents(1, 5s)); + + // Keep "running" far past the cap without finishing. + std::this_thread::sleep_for(500ms); + } + + const auto events = g_recorder.Snapshot(); + + // Exactly one event -- the hang backstop -- and no completion record afterwards. + VERIFY_ARE_EQUAL(events.size(), static_cast(1)); + + const auto& record = events[0]; + // timedOut=true is the proof this is the hang backstop, not the completion path: + // WaitForEvents(1) above gated on the event before the post-cap sleep, so the backstop + // had already fired by scope exit. Elapsed >= maxDuration proves it fired at/after the + // cap. No wall-clock upper bound -- the callback can be delayed under CI load while the + // behavior is still correct, and timedOut=true already distinguishes it from a + // completion record. + VERIFY_IS_TRUE(record.TimedOut); + VERIFY_ARE_EQUAL(record.Name, std::string{"Hang"}); + VERIFY_IS_TRUE(record.Elapsed >= maxDuration); + } +}; + +} // namespace SlowOperationWatcherUnitTests