Log real elapsed time (and hangs) in SlowOperation telemetry#41092
Open
yeelam-gordon wants to merge 1 commit into
Open
Log real elapsed time (and hangs) in SlowOperation telemetry#41092yeelam-gordon wants to merge 1 commit into
yeelam-gordon wants to merge 1 commit into
Conversation
Contributor
There was a problem hiding this comment.
Pull request overview
This PR enhances SlowOperationWatcher telemetry so slow-operation events carry the actual elapsed time and can also surface true hangs via a max-duration backstop, enabling meaningful duration bucketing and distinguishing “slow but finished” from “hung”.
Changes:
- Updated
SlowOperationWatcherto emit at most one telemetry record withelapsedMsandtimedOut, emitting on completion (destructor/Reset()) or atMaxDurationfor hangs. - Added a best-effort max-duration threadpool timer backstop and an injectable sink to support deterministic unit testing.
- Added new TAEF unit tests and wired them into the Windows test CMake target.
Reviewed changes
Copilot reviewed 4 out of 4 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
src/windows/common/SlowOperationWatcher.h |
Extends the watcher contract/API to include max-duration hang detection, event payload struct, and sink injection. |
src/windows/common/SlowOperationWatcher.cpp |
Implements single-emission logic (m_reported), real elapsed measurement, hang backstop timer, and updated telemetry fields. |
test/windows/SlowOperationWatcherUnitTests.cpp |
Adds unit tests validating fast/slow/reset/hang behaviors via an injected recording sink. |
test/windows/CMakeLists.txt |
Adds the new unit test source file to the Windows test build. |
Follow-up to microsoft#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
yeelam-gordon
force-pushed
the
yeelam-gordon/slowoperation-elapsed
branch
from
July 16, 2026 15:10
b576d01 to
8778ff4
Compare
Comment on lines
+165
to
+176
| 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<size_t>(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); | ||
| } |
yeelam-gordon
marked this pull request as ready for review
July 19, 2026 23:58
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Why
Today''s
SlowOperationtelemetry (from #40269) fires once at 10 s and stops, with no duration — so every slow phase looks identical. We can''t tell an 11 s blip from a 5-minute stall; a true hang (operation never returns, destructor never runs) is invisible; and the backend just accumulates a pile of "crossed 10 s" events that carry no insight and nothing to act on.With the real elapsed time we can bucket durations on a dashboard (e.g. 10–30 s / 30–60 s / 1–5 min / hung) and actually see where startup time goes and which phase is regressing — instead of only knowing "something was slow." #40269''s own review flagged this as the follow-up: "we know it was slow, but not how slow… logging elapsed at scope exit would be most useful."
What (only
SlowOperationWatcher; no call sites touched)At most one event, now carrying the real duration:
timedOut=falseevent with the trueelapsedMs.MaxDuration(15 min) → onetimedOut=trueevent, then stop.timedOutis a finished-vs-hung flag, deliberately not success-vs-failure: the watcher is a pure duration timer with no visibility into the operation''s result (a scope that exits by throwing is stilltimedOut=false), and WSL failures often don''t throw, so any inferred success/failure would be unreliable.elapsedMs+timedOutare added fields (backward compatible); new ctor params are defaulted (all 12 callers unchanged); onlyWSL_LOG_TELEMETRYis emitted; construction is best-effort and fullynoexcept, and the timer is drained before teardown → no UAF, and a telemetry failure can never crash or slow the watched operation.Tests (new
SlowOperationWatcherUnitTests.cpp, TAEF — 6/6 passing)FastPathEmitsNothing/DefaultConstructionFastPathEmitsNothing— under threshold stays silent.SlowCompletionEmitsOneRecord— onetimedOut=falsewith real elapsed.ResetAfterThresholdEmitsOnce—Reset()+ destructor emit exactly once.ResetBeforeThresholdEmitsNothing— early disarm stays silent, even if the scope runs long afterReset().HangEmitsOnceAtMaxThenStops— onetimedOut=trueat the cap, no second event on later exit.