Emit telemetry when create-instance steps exceed 10s (#40269)
* Emit telemetry when create-instance steps exceed 10s Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> * Use TraceLoggingValue for SlowOperation name field Matches the codebase convention (100+ uses of TraceLoggingValue elsewhere, zero uses of TraceLoggingString before this PR). Functionally identical: both resolve to the ANSI string field for a const char* argument. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> * Include <exception> explicitly for std::uncaught_exceptions() Addresses review comment: avoid relying on transitive includes. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> * update * resolve comments * resolve comments * update * format src files * resolve comments * resolve comments --------- Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com> Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com>
Shawn Yuan committed
Jun 10, 2026 at 00:13 UTC
6cb0c08568a3a937fa76e553966a1e247ee35470
7 files changed
+193
-5
src/windows/common/CMakeLists.txt
+2
@@ -48,6 +48,7 @@ set(SOURCES
48
WslCoreNetworkingSupport.cpp
49
WslInstall.cpp
50
WslSecurity.cpp
51
+ SlowOperationWatcher.cpp
52
WslTelemetry.cpp
53
wslutil.cpp
54
install.cpp
@@ -133,6 +134,7 @@ set(HEADERS
134
WslCoreNetworkingSupport.h
135
WslInstall.h
136
WslSecurity.h
137
+ SlowOperationWatcher.h
138
WslTelemetry.h
139
wslutil.h
140
EnumVariantMap.h
src/windows/common/SlowOperationWatcher.cpp
new
+76
@@ -0,0 +1,76 @@
1
+/*++
2
+
3
+Copyright (c) Microsoft. All rights reserved.
4
+
5
+Module Name:
6
+
7
+ SlowOperationWatcher.cpp
8
+
9
+Abstract:
10
+
11
+ See header for contract. A single-shot threadpool timer is armed for SlowThreshold
12
+ in the constructor. If it fires, the callback emits one `SlowOperation` telemetry
13
+ event with the phase name and captured std::source_location. The timer is owned by
14
+ wil::unique_threadpool_timer, whose destroyer cancels pending callbacks and blocks
15
+ for any in-flight callback before closing, so OnTimerFired cannot dereference
16
+ `*this` after destruction.
17
+
18
+--*/
19
+
20
+#include "precomp.h"
21
+#include "SlowOperationWatcher.h"
22
+
23
+namespace {
24
+FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept
25
+{
26
+ // Negative FILETIME means "relative to now", in 100ns units. Matches the pattern used
27
+ // elsewhere in the service (see Lifetime.cpp).
28
+ return wil::filetime::from_int64(-wil::filetime_duration::one_millisecond * Relative.count());
29
+}
30
+
31
+// std::source_location::file_name() returns the path as the compiler saw it, which on
32
+// MSVC is an absolute build-agent path. Strip to the basename so telemetry groups the
33
+// same file across different build environments without leaking machine-specific paths.
34
+// The substring is taken from the same null-terminated char array, so the returned view's
35
+// data() is safe to pass to C APIs that expect a null-terminated string.
36
+constexpr std::string_view Basename(std::string_view Path) noexcept
37
+{
38
+ const auto pos = Path.find_last_of("\\/");
39
+ return pos == std::string_view::npos ? Path : Path.substr(pos + 1);
40
+}
41
+
42
+static_assert(Basename("/foo/bar/test.cpp") == "test.cpp");
43
+static_assert(Basename("C:\\src\\test.cpp") == "test.cpp");
44
+static_assert(Basename("no_separator.cpp") == "no_separator.cpp");
45
+} // namespace
46
+
47
+SlowOperationWatcher::SlowOperationWatcher(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location) :
48
+ m_name(Name), m_slowThreshold(SlowThreshold), m_location(Location)
49
+{
50
+ m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr));
51
+ THROW_IF_NULL_ALLOC(m_timer.get());
52
+
53
+ FILETIME due = RelativeFileTime(m_slowThreshold);
54
+ SetThreadpoolTimer(m_timer.get(), &due, 0, 0);
55
+}
56
+
57
+void SlowOperationWatcher::Reset() noexcept
58
+{
59
+ m_timer.reset();
60
+}
61
+
62
+void CALLBACK SlowOperationWatcher::OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept
63
+try
64
+{
65
+ auto* self = static_cast<SlowOperationWatcher*>(Context);
66
+
67
+ WSL_LOG_TELEMETRY(
68
+ "SlowOperation",
69
+ PDT_ProductAndServicePerformance,
70
+ TraceLoggingValue(self->m_name, "name"),
71
+ TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs"),
72
+ TraceLoggingValue(Basename(self->m_location.file_name()).data(), "file"),
73
+ TraceLoggingValue(self->m_location.function_name(), "function"),
74
+ TraceLoggingUInt32(self->m_location.line(), "line"));
75
+}
76
+CATCH_LOG()
src/windows/common/SlowOperationWatcher.h
new
+81
@@ -0,0 +1,81 @@
1
+/*++
2
+
3
+Copyright (c) Microsoft. All rights reserved.
4
+
5
+Module Name:
6
+
7
+ SlowOperationWatcher.h
8
+
9
+Abstract:
10
+
11
+ RAII guard that watches a scoped operation. A threadpool timer is armed in the
12
+ constructor for `SlowThreshold` (10 s default). On the fast path (scope exits
13
+ before the threshold) the watcher's destructor cancels and drains the timer and
14
+ nothing is emitted. If the threshold is reached first -- including while the
15
+ scope is still running or hung indefinitely -- the timer callback fires once,
16
+ emitting a single `SlowOperation` telemetry event carrying the phase name and
17
+ the call site captured via std::source_location, so the backend can attribute
18
+ where time is spent.
19
+
20
+ Usage:
21
+
22
+ SlowOperationWatcher slow{"WaitForMiniInitConnect"};
23
+ m_miniInitChannel = wsl::shared::SocketChannel{AcceptConnection(timeout), ...};
24
+
25
+ If the scope needs to outlive the watched operation (for example to keep a
26
+ pointer into an internal receive buffer alive without a nested block), call
27
+ Reset() to disarm the watcher early:
28
+
29
+ SlowOperationWatcher slow{"WaitForCreateInstanceResult"};
30
+ const auto& result = channel.ReceiveMessage<...>(...);
31
+ slow.Reset();
32
+ // result remains valid and usable here
33
+
34
+--*/
35
+
36
+#pragma once
37
+
38
+#include <windows.h>
39
+#include <wil/resource.h>
40
+#include <chrono>
41
+#include <source_location>
42
+
43
+class SlowOperationWatcher
44
+{
45
+public:
46
+ // Name is restricted to a string-literal reference (const char (&)[N]) to guarantee
47
+ // static storage duration: the raw pointer is dereferenced later from a threadpool
48
+ // callback, so accepting a `const char*` would make UAF via a temporary (e.g.
49
+ // std::string::c_str()) easy. Keep Name a short CamelCase phase identifier that the
50
+ // backend query can switch on (e.g. "WaitForMiniInitConnect").
51
+ template <size_t N>
52
+ explicit SlowOperationWatcher(
53
+ const char (&Name)[N],
54
+ std::chrono::milliseconds SlowThreshold = std::chrono::seconds{10},
55
+ std::source_location Location = std::source_location::current()) :
56
+ SlowOperationWatcher(static_cast<const char*>(Name), SlowThreshold, Location)
57
+ {
58
+ }
59
+
60
+ ~SlowOperationWatcher() noexcept = default;
61
+
62
+ // Disarm the watcher early. After Reset() returns, the threshold callback is
63
+ // guaranteed not to fire. Relies on wil::unique_threadpool_timer's destroyer to
64
+ // cancel pending callbacks and drain any in-flight one.
65
+ void Reset() noexcept;
66
+
67
+ SlowOperationWatcher(const SlowOperationWatcher&) = delete;
68
+ SlowOperationWatcher& operator=(const SlowOperationWatcher&) = delete;
69
+ SlowOperationWatcher(SlowOperationWatcher&&) = delete;
70
+ SlowOperationWatcher& operator=(SlowOperationWatcher&&) = delete;
71
+
72
+private:
73
+ explicit SlowOperationWatcher(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location);
74
+
75
+ static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept;
76
+
77
+ const char* const m_name;
78
+ const std::chrono::milliseconds m_slowThreshold;
79
+ const std::source_location m_location;
80
+ wil::unique_threadpool_timer m_timer;
81
+};
src/windows/common/precomp.h
+1
@@ -135,6 +135,7 @@ Abstract:
135
136
// Telemetry Header
137
#include "WslTelemetry.h"
138
+#include "SlowOperationWatcher.h"
139
140
// LxCore headers
141
#include <lxcoreapi.h>
src/windows/service/exe/PluginManager.cpp
+2
@@ -421,6 +421,7 @@ void PluginManager::OnVmStarted(const WSLSessionInformation* Session, const WSLV
421
WSL_LOG(
422
"PluginOnVmStartedCall", TraceLoggingValue(e.name.c_str(), "Plugin"), TraceLoggingValue(Session->UserSid, "Sid"));
423
424
+ SlowOperationWatcher slowOperation{"PluginOnVmStarted"};
425
ThrowIfPluginError(e.hooks.OnVMStarted(Session, Settings), e.name.c_str());
426
}
427
}
@@ -457,6 +458,7 @@ void PluginManager::OnDistributionStarted(const WSLSessionInformation* Session,
458
TraceLoggingValue(Session->UserSid, "Sid"),
459
TraceLoggingValue(Distribution->Id, "DistributionId"));
460
461
+ SlowOperationWatcher slowOperation{"PluginOnDistributionStarted"};
462
ThrowIfPluginError(e.hooks.OnDistributionStarted(Session, Distribution), e.name.c_str());
463
}
464
}
src/windows/service/exe/WslCoreInstance.cpp
+9
@@ -46,8 +46,12 @@ WslCoreInstance::WslCoreInstance(
46
m_initChannel = std::make_shared<WslCorePort>(InitSocket.release(), m_runtimeId, m_socketTimeout);
47
48
// Read a message from the init daemon. This will let us know if anything failed during startup.
49
+ // The watcher is disarmed as soon as the receive returns so its reported duration reflects
50
+ // only the wait, not the rest of the constructor.
51
gsl::span<gsl::byte> span;
52
+ SlowOperationWatcher slowOperation{"WaitForCreateInstanceResult"};
53
const auto& result = m_initChannel->GetChannel().ReceiveMessage<LX_MINI_INIT_CREATE_INSTANCE_RESULT>(&span, m_socketTimeout);
54
+ slowOperation.Reset();
55
if (result.WarningsOffset != 0)
56
{
57
for (const auto& e : wsl::shared::string::Split<char>(wsl::shared::string::FromSpan(span, result.WarningsOffset), '\n'))
@@ -377,6 +381,7 @@ void WslCoreInstance::Initialize()
381
// If drive mounting is supported, ensure that DrvFs has been initialized.
382
if (WI_IsFlagSet(m_configuration.Flags, LXSS_DISTRO_FLAGS_ENABLE_DRIVE_MOUNTING))
383
{
384
+ SlowOperationWatcher slowOperation{"WaitForDrvFsInit"};
385
drvfsMount = m_initializeDrvFs(m_userToken.get());
386
}
387
@@ -398,8 +403,12 @@ void WslCoreInstance::Initialize()
403
transaction.Send<LX_INIT_CONFIGURATION_INFORMATION>(gsl::span(config));
404
405
// Init replies with information about the distribution.
406
+ // The watcher is disarmed as soon as the receive returns so its reported duration reflects
407
+ // only the wait, not the subsequent interop-server launch.
408
gsl::span<gsl::byte> span;
409
+ SlowOperationWatcher slowOperation{"WaitForInitConfigResponse"};
410
const auto& response = transaction.Receive<LX_INIT_CONFIGURATION_INFORMATION_RESPONSE>(&span);
411
+ slowOperation.Reset();
412
m_defaultUid = response.DefaultUid;
413
m_plan9Port = response.Plan9Port;
414
m_distributionInfo.PidNamespace = response.PidNamespace;
src/windows/service/exe/WslCoreVm.cpp
+22
-5
@@ -324,7 +324,10 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken
324
325
// Create the utility VM and store the runtime ID.
326
std::wstring json = GenerateConfigJson();
327
- m_system = wsl::windows::common::hcs::CreateComputeSystem(m_machineId.c_str(), json.c_str());
327
+ {
328
+ SlowOperationWatcher slowOperation{"HcsCreateSystem"};
329
+ m_system = wsl::windows::common::hcs::CreateComputeSystem(m_machineId.c_str(), json.c_str());
330
+ }
331
m_runtimeId = wsl::windows::common::hcs::GetRuntimeId(m_system.get());
332
WI_ASSERT(IsEqualGUID(VmId, m_runtimeId));
333
@@ -349,6 +352,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken
352
// Start the utility VM.
353
try
354
{
355
+ SlowOperationWatcher slowOperation{"HcsStartSystem"};
356
wsl::windows::common::hcs::StartComputeSystem(m_system.get(), json.c_str());
357
}
358
catch (...)
@@ -416,14 +420,20 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken
420
}
421
422
// Accept a connection from mini_init with a receive timeout so the service does not get stuck waiting for a response from the VM.
419
- m_miniInitChannel =
420
- wsl::shared::SocketChannel{AcceptConnection(m_vmConfig.KernelBootTimeout), "mini_init", {m_terminatingEvent.get()}};
423
+ {
424
+ SlowOperationWatcher slowOperation{"WaitForMiniInitConnect"};
425
+ m_miniInitChannel =
426
+ wsl::shared::SocketChannel{AcceptConnection(m_vmConfig.KernelBootTimeout), "mini_init", {m_terminatingEvent.get()}};
427
+ }
428
429
// Accept the connection from the Linux guest for notifications.
430
m_notifyChannel = AcceptConnection(m_vmConfig.KernelBootTimeout);
431
432
// Receive and parse the guest kernel version
426
- ReadGuestCapabilities();
433
+ {
434
+ SlowOperationWatcher slowOperation{"ReadGuestCapabilities"};
435
+ ReadGuestCapabilities();
436
+ }
437
438
// Cache the effective swiotlb configuration. The kernel picks a valid GPA, allocates the pool,
439
// and publishes the actual (base, size) via sysfs. Only warn when swiotlb was actually
@@ -567,7 +577,10 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken
577
wsl::windows::common::hcs::unique_hcn_network natNetwork;
578
if (m_vmConfig.NetworkingMode == NetworkingMode::Nat)
579
{
570
- natNetwork = wsl::core::NatNetworking::CreateNetwork(m_vmConfig);
580
+ {
581
+ SlowOperationWatcher slowOperation{"CreateNatNetwork"};
582
+ natNetwork = wsl::core::NatNetworking::CreateNetwork(m_vmConfig);
583
+ }
584
if (!natNetwork)
585
{
586
EMIT_USER_WARNING(wsl::shared::Localization::MessageNetworkInitializationFailedFallback2(
@@ -1163,7 +1176,9 @@ std::shared_ptr<LxssRunningInstance> WslCoreVm::CreateInstance(
1176
{
1177
// Add the VHD to the machine.
1178
auto lock = m_lock.lock_exclusive();
1179
+ SlowOperationWatcher slowOperation{"AttachDistroVhd"};
1180
const auto lun = AttachDiskLockHeld(Configuration.VhdFilePath.c_str(), DiskType::VHD, MountFlags::None, {}, false, m_userToken.get());
1181
+ slowOperation.Reset();
1182
1183
// Launch the init daemon and create the instance.
1184
int flags = LxMiniInitMessageFlagNone;
@@ -1227,7 +1242,9 @@ std::shared_ptr<LxssRunningInstance> WslCoreVm::CreateInstanceInternal(
1242
WI_ClearFlagIf(localConfig.Flags, LXSS_DISTRO_FLAGS_ENABLE_DRIVE_MOUNTING, !m_vmConfig.EnableHostFileSystemAccess);
1243
1244
// Establish a communication channel with the init daemon.
1245
+ SlowOperationWatcher slowOperation{"WaitForInitDaemonConnect"};
1246
auto initSocket = AcceptConnection(ReceiveTimeout);
1247
+ slowOperation.Reset();
1248
1249
// If the system distro is enabled, establish a communication channel with its init daemon.
1250
wil::unique_socket systemDistroSocket;