diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp index e08a51591..52265f16c 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 55b86c637..76ecb17c9 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 54831cd62..f6ac80fbf 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 000000000..dead24345 --- /dev/null +++ b/test/windows/SlowOperationWatcherUnitTests.cpp @@ -0,0 +1,265 @@ +/*++ + +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) + { + constexpr auto threshold = 50ms; + { + 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 well + // past the threshold. The destructor at scope exit must still emit nothing. + std::this_thread::sleep_for(150ms); + } + + 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