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

Author: yeelam-gordon

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<Duration>(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<SlowOperationWatcher*>(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()

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 <windows.h>
 #include <wil/resource.h>
+#include <atomic>
 #include <chrono>
 #include <source_location>
 
 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 <size_t N>
     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<const char*>(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<const char*>(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<bool> m_reported; // set once the single event has been emitted (by either path)
     wil::unique_threadpool_timer m_timer;
 };

test/windows/CMakeLists.txt

@@ -10,6 +10,7 @@ set(SOURCES
     PolicyTests.cpp
     InstallerTests.cpp
     WSLCTests.cpp
+    SlowOperationWatcherUnitTests.cpp
     WslcSdkTests.cpp
     WslcSdkWinRtTests.cpp
     WindowsUpdateTests.cpp)