From 76192d4928d73ec98fbac5f7b42ef5d373234b16 Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Wed, 22 Apr 2026 15:42:46 +0800 Subject: [PATCH 01/10] Emit telemetry when create-instance steps exceed 10s Co-Authored-By: Claude Opus 4.7 (1M context) --- src/windows/common/CMakeLists.txt | 2 + src/windows/common/WslSlowOperation.cpp | 102 ++++++++++++++++++++ src/windows/common/WslSlowOperation.h | 62 ++++++++++++ src/windows/common/precomp.h | 1 + src/windows/service/exe/PluginManager.cpp | 2 + src/windows/service/exe/WslCoreInstance.cpp | 19 +++- src/windows/service/exe/WslCoreVm.cpp | 47 +++++++-- 7 files changed, 224 insertions(+), 11 deletions(-) create mode 100644 src/windows/common/WslSlowOperation.cpp create mode 100644 src/windows/common/WslSlowOperation.h diff --git a/src/windows/common/CMakeLists.txt b/src/windows/common/CMakeLists.txt index 6dbe4c0b1..3d09d2826 100644 --- a/src/windows/common/CMakeLists.txt +++ b/src/windows/common/CMakeLists.txt @@ -42,6 +42,7 @@ set(SOURCES WslCoreNetworkingSupport.cpp WslInstall.cpp WslSecurity.cpp + WslSlowOperation.cpp WslTelemetry.cpp VirtioNetworking.cpp wslutil.cpp @@ -119,6 +120,7 @@ set(HEADERS WslCoreNetworkingSupport.h WslInstall.h WslSecurity.h + WslSlowOperation.h WslTelemetry.h VirtioNetworking.h wslutil.h diff --git a/src/windows/common/WslSlowOperation.cpp b/src/windows/common/WslSlowOperation.cpp new file mode 100644 index 000000000..78dbdbb4f --- /dev/null +++ b/src/windows/common/WslSlowOperation.cpp @@ -0,0 +1,102 @@ +/*++ + +Copyright (c) Microsoft. All rights reserved. + +Module Name: + + WslSlowOperation.cpp + +Abstract: + + See header for contract. A single threadpool timer is armed in the constructor for + SlowThreshold; if it fires, the callback records that the operation went slow and + emits SlowOperationStarted telemetry + log. The destructor cancels and drains the + timer (so the callback cannot touch *this after destruction) and, if the callback + already fired, emits a terminating SlowOperationEnded event with the final elapsed + time. + +--*/ + +#include "precomp.h" +#include "WslSlowOperation.h" + +namespace { +FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept +{ + // Negative FILETIME means "relative to now", in 100ns units. + ULARGE_INTEGER due{}; + due.QuadPart = static_cast(-(Relative.count() * 10'000LL)); + FILETIME ft{}; + ft.dwLowDateTime = due.LowPart; + ft.dwHighDateTime = due.HighPart; + return ft; +} +} // namespace + +WslSlowOperation::WslSlowOperation(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold) : + m_name(Name), m_slowThreshold(SlowThreshold), m_start(std::chrono::steady_clock::now()), m_uncaughtOnEntry(std::uncaught_exceptions()) +{ + m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); + THROW_LAST_ERROR_IF_NULL(m_timer); + + FILETIME due = RelativeFileTime(m_slowThreshold); + SetThreadpoolTimer(m_timer.get(), &due, 0, 0); +} + +WslSlowOperation::~WslSlowOperation() noexcept +{ + // Cancel any pending fire, then block until an in-flight callback drains. This is + // the guarantee that OnTimerFired will not dereference `this` after destruction. + if (m_timer) + { + SetThreadpoolTimer(m_timer.get(), nullptr, 0, 0); + WaitForThreadpoolTimerCallbacks(m_timer.get(), TRUE); + } + + if (!m_fired.load(std::memory_order_acquire)) + { + return; + } + + const auto elapsed = std::chrono::duration_cast(std::chrono::steady_clock::now() - m_start); + + // Mirror the idiom used elsewhere in the codebase: avoid calling + // wil::ResultFromCaughtException from a destructor (UB outside a catch handler); + // use uncaught_exceptions() delta to surface "did this scope unwind?" only. + const HRESULT hr = (std::uncaught_exceptions() > m_uncaughtOnEntry) ? E_FAIL : S_OK; + + try + { + WSL_LOG_TELEMETRY( + "SlowOperationEnded", + PDT_ProductAndServicePerformance, + TraceLoggingString(m_name, "name"), + TraceLoggingInt64(elapsed.count(), "elapsedMs"), + TraceLoggingHResult(hr, "hr")); + } + CATCH_LOG() +} + +void CALLBACK WslSlowOperation::OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept +try +{ + auto* self = static_cast(Context); + if (!self->m_fired.exchange(true, std::memory_order_acq_rel)) + { + self->EmitSlowThresholdCrossed(); + } +} +CATCH_LOG() + +void WslSlowOperation::EmitSlowThresholdCrossed() noexcept +try +{ + WSL_LOG_TELEMETRY( + "SlowOperationStarted", + PDT_ProductAndServicePerformance, + TraceLoggingString(m_name, "name"), + TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); + + WSL_LOG("SlowOperation", TraceLoggingString(m_name, "name"), TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); +} +CATCH_LOG() diff --git a/src/windows/common/WslSlowOperation.h b/src/windows/common/WslSlowOperation.h new file mode 100644 index 000000000..a44ce1d3c --- /dev/null +++ b/src/windows/common/WslSlowOperation.h @@ -0,0 +1,62 @@ +/*++ + +Copyright (c) Microsoft. All rights reserved. + +Module Name: + + WslSlowOperation.h + +Abstract: + + RAII guard that watches a scoped operation. On the fast path (operation completes under + the slow threshold) nothing is emitted. When the slow threshold is crossed the guard + emits a `SlowOperationStarted` telemetry event plus a `SlowOperation` debug log so the + backend can attribute where time is spent; on scope exit it emits a terminating + `SlowOperationEnded` event carrying the final elapsed time and hr (E_FAIL if the + scope exits via exception, S_OK otherwise). + + Usage: + + WslSlowOperation slow{"WaitForMiniInitConnect"}; + m_miniInitChannel = wsl::shared::SocketChannel{AcceptConnection(timeout), ...}; + +--*/ + +#pragma once + +#include +#include +#include +#include + +class WslSlowOperation +{ +public: + // Name must have static storage duration (string literal). It is emitted verbatim into + // telemetry and log, so keep it a short CamelCase phase identifier that the backend + // query can switch on (e.g. "WaitForMiniInitConnect"). + explicit WslSlowOperation(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold = std::chrono::seconds{10}); + + ~WslSlowOperation() noexcept; + + WslSlowOperation(const WslSlowOperation&) = delete; + WslSlowOperation& operator=(const WslSlowOperation&) = delete; + WslSlowOperation(WslSlowOperation&&) = delete; + WslSlowOperation& operator=(WslSlowOperation&&) = delete; + +private: + static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept; + + void EmitSlowThresholdCrossed() noexcept; + + const char* const m_name; + const std::chrono::milliseconds m_slowThreshold; + const std::chrono::steady_clock::time_point m_start; + const int m_uncaughtOnEntry; + + // Set to true by the timer callback when the slow threshold is crossed; read by the + // destructor to decide whether to emit SlowOperationEnded. exchange() in the callback + // is defensive (the timer is a single-shot so the callback only runs once anyway). + std::atomic m_fired{false}; + wil::unique_threadpool_timer m_timer; +}; diff --git a/src/windows/common/precomp.h b/src/windows/common/precomp.h index 08a8140c1..e3b7a64f8 100644 --- a/src/windows/common/precomp.h +++ b/src/windows/common/precomp.h @@ -134,6 +134,7 @@ Module Name: // Telemetry Header #include "WslTelemetry.h" +#include "WslSlowOperation.h" // LxCore headers #include diff --git a/src/windows/service/exe/PluginManager.cpp b/src/windows/service/exe/PluginManager.cpp index e4d23f226..fcd64dc9f 100644 --- a/src/windows/service/exe/PluginManager.cpp +++ b/src/windows/service/exe/PluginManager.cpp @@ -181,6 +181,7 @@ void PluginManager::OnVmStarted(const WSLSessionInformation* Session, const WSLV WSL_LOG( "PluginOnVmStartedCall", TraceLoggingValue(e.name.c_str(), "Plugin"), TraceLoggingValue(Session->UserSid, "Sid")); + WslSlowOperation slowOperation{"PluginOnVmStarted"}; ThrowIfPluginError(e.hooks.OnVMStarted(Session, Settings), Session->SessionId, e.name.c_str()); } } @@ -217,6 +218,7 @@ void PluginManager::OnDistributionStarted(const WSLSessionInformation* Session, TraceLoggingValue(Session->UserSid, "Sid"), TraceLoggingValue(Distribution->Id, "DistributionId")); + WslSlowOperation slowOperation{"PluginOnDistributionStarted"}; ThrowIfPluginError(e.hooks.OnDistributionStarted(Session, Distribution), Session->SessionId, e.name.c_str()); } } diff --git a/src/windows/service/exe/WslCoreInstance.cpp b/src/windows/service/exe/WslCoreInstance.cpp index 98b7379c4..5590f8521 100644 --- a/src/windows/service/exe/WslCoreInstance.cpp +++ b/src/windows/service/exe/WslCoreInstance.cpp @@ -44,8 +44,15 @@ WslCoreInstance::WslCoreInstance( m_initChannel = std::make_shared(InitSocket.release(), m_runtimeId, m_socketTimeout); // Read a message from the init daemon. This will let us know if anything failed during startup. + // The WslSlowOperation scope is narrowed to the receive so the reported duration reflects the + // wait, not the rest of the constructor. gsl::span span; - const auto& result = m_initChannel->GetChannel().ReceiveMessage(&span, m_socketTimeout); + const LX_MINI_INIT_CREATE_INSTANCE_RESULT* resultPtr = nullptr; + { + WslSlowOperation slowOperation{"WaitForCreateInstanceResult"}; + resultPtr = &m_initChannel->GetChannel().ReceiveMessage(&span, m_socketTimeout); + } + const auto& result = *resultPtr; if (result.WarningsOffset != 0) { for (const auto& e : wsl::shared::string::Split(wsl::shared::string::FromSpan(span, result.WarningsOffset), '\n')) @@ -373,6 +380,7 @@ void WslCoreInstance::Initialize() // If drive mounting is supported, ensure that DrvFs has been initialized. if (WI_IsFlagSet(m_configuration.Flags, LXSS_DISTRO_FLAGS_ENABLE_DRIVE_MOUNTING)) { + WslSlowOperation slowOperation{"WaitForDrvFsInit"}; drvfsMount = m_initializeDrvFs(m_userToken.get()); } @@ -394,8 +402,15 @@ void WslCoreInstance::Initialize() transaction.Send(gsl::span(config)); // Init replies with information about the distribution. + // The WslSlowOperation scope is narrowed to the receive so the reported duration reflects the + // wait, not the subsequent interop-server launch. gsl::span span; - const auto& response = transaction.Receive(&span); + const LX_INIT_CONFIGURATION_INFORMATION_RESPONSE* responsePtr = nullptr; + { + WslSlowOperation slowOperation{"WaitForInitConfigResponse"}; + responsePtr = &transaction.Receive(&span); + } + const auto& response = *responsePtr; m_defaultUid = response.DefaultUid; m_plan9Port = response.Plan9Port; m_distributionInfo.PidNamespace = response.PidNamespace; diff --git a/src/windows/service/exe/WslCoreVm.cpp b/src/windows/service/exe/WslCoreVm.cpp index 469ca5e6e..47bce6033 100644 --- a/src/windows/service/exe/WslCoreVm.cpp +++ b/src/windows/service/exe/WslCoreVm.cpp @@ -321,7 +321,10 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Create the utility VM and store the runtime ID. std::wstring json = GenerateConfigJson(); - m_system = wsl::windows::common::hcs::CreateComputeSystem(m_machineId.c_str(), json.c_str()); + { + WslSlowOperation slowOperation{"HcsCreateSystem"}; + m_system = wsl::windows::common::hcs::CreateComputeSystem(m_machineId.c_str(), json.c_str()); + } m_runtimeId = wsl::windows::common::hcs::GetRuntimeId(m_system.get()); WI_ASSERT(IsEqualGUID(VmId, m_runtimeId)); @@ -346,6 +349,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Start the utility VM. try { + WslSlowOperation slowOperation{"HcsStartSystem"}; wsl::windows::common::hcs::StartComputeSystem(m_system.get(), json.c_str()); } catch (...) @@ -436,13 +440,20 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken } // Accept a connection from mini_init with a receive timeout so the service does not get stuck waiting for a response from the VM. - m_miniInitChannel = wsl::shared::SocketChannel{AcceptConnection(m_vmConfig.KernelBootTimeout), "mini_init", m_terminatingEvent.get()}; + { + WslSlowOperation slowOperation{"WaitForMiniInitConnect"}; + m_miniInitChannel = + wsl::shared::SocketChannel{AcceptConnection(m_vmConfig.KernelBootTimeout), "mini_init", m_terminatingEvent.get()}; + } // Accept the connection from the Linux guest for notifications. m_notifyChannel = AcceptConnection(m_vmConfig.KernelBootTimeout); // Receive and parse the guest kernel version - ReadGuestCapabilities(); + { + WslSlowOperation slowOperation{"ReadGuestCapabilities"}; + ReadGuestCapabilities(); + } // Mount the system distro. // N.B. If using SCSI, the system distro is added during VM creation. @@ -532,6 +543,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken { ExecutionContext context(Context::ConfigureNetworking); + WslSlowOperation slowOperation{"ConfigureNetworking"}; // Accept the connection from the guest network service and create the channel. wsl::core::GnsChannel gnsChannel(AcceptConnection(m_vmConfig.KernelBootTimeout)); @@ -551,7 +563,10 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken wsl::windows::common::hcs::unique_hcn_network natNetwork; if (m_vmConfig.NetworkingMode == NetworkingMode::Nat) { - natNetwork = wsl::core::NatNetworking::CreateNetwork(m_vmConfig); + { + WslSlowOperation slowOperation{"CreateNatNetwork"}; + natNetwork = wsl::core::NatNetworking::CreateNetwork(m_vmConfig); + } if (!natNetwork) { EMIT_USER_WARNING(wsl::shared::Localization::MessageNetworkInitializationFailedFallback2( @@ -660,7 +675,10 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken } // Perform additional initialization. - InitializeGuest(); + { + WslSlowOperation slowOperation{"InitializeGuest"}; + InitializeGuest(); + } } WslCoreVm::~WslCoreVm() noexcept @@ -1168,7 +1186,11 @@ std::shared_ptr WslCoreVm::CreateInstance( { // Add the VHD to the machine. auto lock = m_lock.lock_exclusive(); - const auto lun = AttachDiskLockHeld(Configuration.VhdFilePath.c_str(), DiskType::VHD, MountFlags::None, {}, false, m_userToken.get()); + ULONG lun = 0; + { + WslSlowOperation slowOperation{"AttachDistroVhd"}; + lun = AttachDiskLockHeld(Configuration.VhdFilePath.c_str(), DiskType::VHD, MountFlags::None, {}, false, m_userToken.get()); + } // Launch the init daemon and create the instance. int flags = LxMiniInitMessageFlagNone; @@ -1208,8 +1230,11 @@ std::shared_ptr WslCoreVm::CreateInstance( message.WriteString(message->SharedMemoryRootOffset, sharedMemoryRoot); message.WriteString(message->InstallPathOffset, installPath); message.WriteString(message->UserProfileOffset, userProfile); - auto transaction = m_miniInitChannel.StartTransaction(); - transaction.Send(message.Span()); + { + WslSlowOperation slowOperation{"SendLaunchInit"}; + auto transaction = m_miniInitChannel.StartTransaction(); + transaction.Send(message.Span()); + } return CreateInstanceInternal( InstanceId, Configuration, ReceiveTimeout, DefaultUid, ClientLifetimeId, WI_IsFlagSet(flags, LxMiniInitMessageFlagLaunchSystemDistro), ConnectPort); @@ -1232,7 +1257,11 @@ std::shared_ptr WslCoreVm::CreateInstanceInternal( WI_ClearFlagIf(localConfig.Flags, LXSS_DISTRO_FLAGS_ENABLE_DRIVE_MOUNTING, !m_vmConfig.EnableHostFileSystemAccess); // Establish a communication channel with the init daemon. - auto initSocket = AcceptConnection(ReceiveTimeout); + wil::unique_socket initSocket; + { + WslSlowOperation slowOperation{"WaitForInitDaemonConnect"}; + initSocket = AcceptConnection(ReceiveTimeout); + } // If the system distro is enabled, establish a communication channel with its init daemon. wil::unique_socket systemDistroSocket; From 11e87752e0cc6378c61588dc10d755f1eb141b21 Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Wed, 22 Apr 2026 16:02:10 +0800 Subject: [PATCH 02/10] 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) --- src/windows/common/WslSlowOperation.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/windows/common/WslSlowOperation.cpp b/src/windows/common/WslSlowOperation.cpp index 78dbdbb4f..3544ce89b 100644 --- a/src/windows/common/WslSlowOperation.cpp +++ b/src/windows/common/WslSlowOperation.cpp @@ -70,7 +70,7 @@ WslSlowOperation::~WslSlowOperation() noexcept WSL_LOG_TELEMETRY( "SlowOperationEnded", PDT_ProductAndServicePerformance, - TraceLoggingString(m_name, "name"), + TraceLoggingValue(m_name, "name"), TraceLoggingInt64(elapsed.count(), "elapsedMs"), TraceLoggingHResult(hr, "hr")); } @@ -94,9 +94,9 @@ try WSL_LOG_TELEMETRY( "SlowOperationStarted", PDT_ProductAndServicePerformance, - TraceLoggingString(m_name, "name"), + TraceLoggingValue(m_name, "name"), TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); - WSL_LOG("SlowOperation", TraceLoggingString(m_name, "name"), TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); + WSL_LOG("SlowOperation", TraceLoggingValue(m_name, "name"), TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); } CATCH_LOG() From 218e0883b07434243cfd50eb7b18bee35629d4e0 Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Wed, 22 Apr 2026 16:19:18 +0800 Subject: [PATCH 03/10] Include explicitly for std::uncaught_exceptions() Addresses review comment: avoid relying on transitive includes. Co-Authored-By: Claude Opus 4.7 (1M context) --- src/windows/common/WslSlowOperation.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/windows/common/WslSlowOperation.cpp b/src/windows/common/WslSlowOperation.cpp index 3544ce89b..ed3bdd90f 100644 --- a/src/windows/common/WslSlowOperation.cpp +++ b/src/windows/common/WslSlowOperation.cpp @@ -20,6 +20,8 @@ Module Name: #include "precomp.h" #include "WslSlowOperation.h" +#include + namespace { FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept { From 56cb403f2b77f00251c0bc13a2728a9cb410160d Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Wed, 22 Apr 2026 17:16:50 +0800 Subject: [PATCH 04/10] update --- src/shared/inc/message.h | 2 +- src/windows/common/WslSlowOperation.cpp | 60 ++++++------------------- src/windows/common/WslSlowOperation.h | 23 +++------- 3 files changed, 21 insertions(+), 64 deletions(-) diff --git a/src/shared/inc/message.h b/src/shared/inc/message.h index b4b946644..6f9cd77c0 100644 --- a/src/shared/inc/message.h +++ b/src/shared/inc/message.h @@ -171,7 +171,7 @@ class MessageWriter const auto* bufferStart = reinterpret_cast(m_buffer.data()); // Validate that 'Index' is actually within the bounds of our buffer - assert(indexPtr >= bufferStart && indexPtr + sizeof(index) <= bufferStart + m_buffer.size()); + assert(indexPtr >= bufferStart && indexPtr + sizeof(Index) <= bufferStart + m_buffer.size()); return static_cast(indexPtr - bufferStart); } diff --git a/src/windows/common/WslSlowOperation.cpp b/src/windows/common/WslSlowOperation.cpp index ed3bdd90f..d8cd9a99c 100644 --- a/src/windows/common/WslSlowOperation.cpp +++ b/src/windows/common/WslSlowOperation.cpp @@ -8,20 +8,17 @@ Module Name: Abstract: - See header for contract. A single threadpool timer is armed in the constructor for - SlowThreshold; if it fires, the callback records that the operation went slow and - emits SlowOperationStarted telemetry + log. The destructor cancels and drains the - timer (so the callback cannot touch *this after destruction) and, if the callback - already fired, emits a terminating SlowOperationEnded event with the final elapsed - time. + 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 plus a matching debug log. The destructor cancels and drains the timer + (WaitForThreadpoolTimerCallbacks with fCancelPendingCallbacks=TRUE), so the + callback is guaranteed not to dereference `*this` after destruction. --*/ #include "precomp.h" #include "WslSlowOperation.h" -#include - namespace { FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept { @@ -36,7 +33,7 @@ FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept } // namespace WslSlowOperation::WslSlowOperation(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold) : - m_name(Name), m_slowThreshold(SlowThreshold), m_start(std::chrono::steady_clock::now()), m_uncaughtOnEntry(std::uncaught_exceptions()) + m_name(Name), m_slowThreshold(SlowThreshold) { m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); THROW_LAST_ERROR_IF_NULL(m_timer); @@ -47,58 +44,27 @@ WslSlowOperation::WslSlowOperation(_In_z_ const char* Name, std::chrono::millise WslSlowOperation::~WslSlowOperation() noexcept { - // Cancel any pending fire, then block until an in-flight callback drains. This is - // the guarantee that OnTimerFired will not dereference `this` after destruction. + // Cancel any pending fire and block until an in-flight callback drains. This is the + // guarantee that OnTimerFired will not dereference `this` after destruction. if (m_timer) { SetThreadpoolTimer(m_timer.get(), nullptr, 0, 0); WaitForThreadpoolTimerCallbacks(m_timer.get(), TRUE); } - - if (!m_fired.load(std::memory_order_acquire)) - { - return; - } - - const auto elapsed = std::chrono::duration_cast(std::chrono::steady_clock::now() - m_start); - - // Mirror the idiom used elsewhere in the codebase: avoid calling - // wil::ResultFromCaughtException from a destructor (UB outside a catch handler); - // use uncaught_exceptions() delta to surface "did this scope unwind?" only. - const HRESULT hr = (std::uncaught_exceptions() > m_uncaughtOnEntry) ? E_FAIL : S_OK; - - try - { - WSL_LOG_TELEMETRY( - "SlowOperationEnded", - PDT_ProductAndServicePerformance, - TraceLoggingValue(m_name, "name"), - TraceLoggingInt64(elapsed.count(), "elapsedMs"), - TraceLoggingHResult(hr, "hr")); - } - CATCH_LOG() } void CALLBACK WslSlowOperation::OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept try { auto* self = static_cast(Context); - if (!self->m_fired.exchange(true, std::memory_order_acq_rel)) - { - self->EmitSlowThresholdCrossed(); - } -} -CATCH_LOG() -void WslSlowOperation::EmitSlowThresholdCrossed() noexcept -try -{ WSL_LOG_TELEMETRY( - "SlowOperationStarted", + "SlowOperation", PDT_ProductAndServicePerformance, - TraceLoggingValue(m_name, "name"), - TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); + TraceLoggingValue(self->m_name, "name"), + TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs")); - WSL_LOG("SlowOperation", TraceLoggingValue(m_name, "name"), TraceLoggingInt64(m_slowThreshold.count(), "thresholdMs")); + WSL_LOG( + "SlowOperation", TraceLoggingValue(self->m_name, "name"), TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs")); } CATCH_LOG() diff --git a/src/windows/common/WslSlowOperation.h b/src/windows/common/WslSlowOperation.h index a44ce1d3c..07bdbab48 100644 --- a/src/windows/common/WslSlowOperation.h +++ b/src/windows/common/WslSlowOperation.h @@ -8,12 +8,13 @@ Module Name: Abstract: - RAII guard that watches a scoped operation. On the fast path (operation completes under - the slow threshold) nothing is emitted. When the slow threshold is crossed the guard - emits a `SlowOperationStarted` telemetry event plus a `SlowOperation` debug log so the - backend can attribute where time is spent; on scope exit it emits a terminating - `SlowOperationEnded` event carrying the final elapsed time and hr (E_FAIL if the - scope exits via exception, S_OK otherwise). + 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 destructor cancels 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 plus a matching debug log so the backend can + attribute where time is spent. Usage: @@ -26,7 +27,6 @@ Module Name: #include #include -#include #include class WslSlowOperation @@ -47,16 +47,7 @@ class WslSlowOperation private: static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept; - void EmitSlowThresholdCrossed() noexcept; - const char* const m_name; const std::chrono::milliseconds m_slowThreshold; - const std::chrono::steady_clock::time_point m_start; - const int m_uncaughtOnEntry; - - // Set to true by the timer callback when the slow threshold is crossed; read by the - // destructor to decide whether to emit SlowOperationEnded. exchange() in the callback - // is defensive (the timer is a single-shot so the callback only runs once anyway). - std::atomic m_fired{false}; wil::unique_threadpool_timer m_timer; }; From 577833c4748b9562e44f73d4da44ce43fe5d660e Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Thu, 23 Apr 2026 10:06:31 +0800 Subject: [PATCH 05/10] resolve comments --- src/windows/common/CMakeLists.txt | 4 +- src/windows/common/SlowOperationWatcher.cpp | 66 +++++++++++++++++++ src/windows/common/SlowOperationWatcher.h | 73 +++++++++++++++++++++ src/windows/common/WslSlowOperation.cpp | 70 -------------------- src/windows/common/WslSlowOperation.h | 53 --------------- src/windows/common/precomp.h | 2 +- src/windows/service/exe/PluginManager.cpp | 4 +- src/windows/service/exe/WslCoreInstance.cpp | 28 ++++---- src/windows/service/exe/WslCoreVm.cpp | 20 +++--- 9 files changed, 165 insertions(+), 155 deletions(-) create mode 100644 src/windows/common/SlowOperationWatcher.cpp create mode 100644 src/windows/common/SlowOperationWatcher.h delete mode 100644 src/windows/common/WslSlowOperation.cpp delete mode 100644 src/windows/common/WslSlowOperation.h diff --git a/src/windows/common/CMakeLists.txt b/src/windows/common/CMakeLists.txt index 3d09d2826..cd889d59b 100644 --- a/src/windows/common/CMakeLists.txt +++ b/src/windows/common/CMakeLists.txt @@ -42,7 +42,7 @@ set(SOURCES WslCoreNetworkingSupport.cpp WslInstall.cpp WslSecurity.cpp - WslSlowOperation.cpp + SlowOperationWatcher.cpp WslTelemetry.cpp VirtioNetworking.cpp wslutil.cpp @@ -120,7 +120,7 @@ set(HEADERS WslCoreNetworkingSupport.h WslInstall.h WslSecurity.h - WslSlowOperation.h + SlowOperationWatcher.h WslTelemetry.h VirtioNetworking.h wslutil.h diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp new file mode 100644 index 000000000..64863657c --- /dev/null +++ b/src/windows/common/SlowOperationWatcher.cpp @@ -0,0 +1,66 @@ +/*++ + +Copyright (c) Microsoft. All rights reserved. + +Module Name: + + SlowOperationWatcher.cpp + +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. + +--*/ + +#include "precomp.h" +#include "SlowOperationWatcher.h" + +namespace { +FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept +{ + // Negative FILETIME means "relative to now", in 100ns units. + ULARGE_INTEGER due{}; + due.QuadPart = static_cast(-(Relative.count() * 10'000LL)); + FILETIME ft{}; + ft.dwLowDateTime = due.LowPart; + ft.dwHighDateTime = due.HighPart; + return ft; +} +} // 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) +{ + m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); + THROW_LAST_ERROR_IF_NULL(m_timer.get()); + + FILETIME due = RelativeFileTime(m_slowThreshold); + SetThreadpoolTimer(m_timer.get(), &due, 0, 0); +} + +void SlowOperationWatcher::Reset() noexcept +{ + m_timer.reset(); +} + +void CALLBACK SlowOperationWatcher::OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept +try +{ + auto* self = static_cast(Context); + + WSL_LOG_TELEMETRY( + "SlowOperation", + PDT_ProductAndServicePerformance, + TraceLoggingValue(self->m_name, "name"), + TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs"), + TraceLoggingValue(self->m_location.file_name(), "file"), + TraceLoggingValue(self->m_location.function_name(), "function"), + TraceLoggingUInt32(self->m_location.line(), "line")); +} +CATCH_LOG() diff --git a/src/windows/common/SlowOperationWatcher.h b/src/windows/common/SlowOperationWatcher.h new file mode 100644 index 000000000..4780a5ade --- /dev/null +++ b/src/windows/common/SlowOperationWatcher.h @@ -0,0 +1,73 @@ +/*++ + +Copyright (c) Microsoft. All rights reserved. + +Module Name: + + SlowOperationWatcher.h + +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. + + Usage: + + SlowOperationWatcher slow{"WaitForMiniInitConnect"}; + m_miniInitChannel = wsl::shared::SocketChannel{AcceptConnection(timeout), ...}; + + If the scope needs to outlive the watched operation (for example to keep a + pointer into an internal receive buffer alive without a nested block), call + Reset() to disarm the watcher early: + + SlowOperationWatcher slow{"WaitForCreateInstanceResult"}; + const auto& result = channel.ReceiveMessage<...>(...); + slow.Reset(); + // result remains valid and usable here + +--*/ + +#pragma once + +#include +#include +#include +#include + +class SlowOperationWatcher +{ +public: + // Name must have static storage duration (string literal). It is emitted verbatim into + // telemetry, so keep it a short CamelCase phase identifier that the backend query can + // switch on (e.g. "WaitForMiniInitConnect"). + explicit SlowOperationWatcher( + _In_z_ const char* Name, + std::chrono::milliseconds SlowThreshold = std::chrono::seconds{10}, + std::source_location Location = std::source_location::current()); + + ~SlowOperationWatcher() noexcept = default; + + // 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. + void Reset() noexcept; + + SlowOperationWatcher(const SlowOperationWatcher&) = delete; + SlowOperationWatcher& operator=(const SlowOperationWatcher&) = delete; + SlowOperationWatcher(SlowOperationWatcher&&) = delete; + SlowOperationWatcher& operator=(SlowOperationWatcher&&) = delete; + +private: + static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept; + + const char* const m_name; + const std::chrono::milliseconds m_slowThreshold; + const std::source_location m_location; + wil::unique_threadpool_timer m_timer; +}; diff --git a/src/windows/common/WslSlowOperation.cpp b/src/windows/common/WslSlowOperation.cpp deleted file mode 100644 index d8cd9a99c..000000000 --- a/src/windows/common/WslSlowOperation.cpp +++ /dev/null @@ -1,70 +0,0 @@ -/*++ - -Copyright (c) Microsoft. All rights reserved. - -Module Name: - - WslSlowOperation.cpp - -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 plus a matching debug log. The destructor cancels and drains the timer - (WaitForThreadpoolTimerCallbacks with fCancelPendingCallbacks=TRUE), so the - callback is guaranteed not to dereference `*this` after destruction. - ---*/ - -#include "precomp.h" -#include "WslSlowOperation.h" - -namespace { -FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept -{ - // Negative FILETIME means "relative to now", in 100ns units. - ULARGE_INTEGER due{}; - due.QuadPart = static_cast(-(Relative.count() * 10'000LL)); - FILETIME ft{}; - ft.dwLowDateTime = due.LowPart; - ft.dwHighDateTime = due.HighPart; - return ft; -} -} // namespace - -WslSlowOperation::WslSlowOperation(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold) : - m_name(Name), m_slowThreshold(SlowThreshold) -{ - m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); - THROW_LAST_ERROR_IF_NULL(m_timer); - - FILETIME due = RelativeFileTime(m_slowThreshold); - SetThreadpoolTimer(m_timer.get(), &due, 0, 0); -} - -WslSlowOperation::~WslSlowOperation() noexcept -{ - // Cancel any pending fire and block until an in-flight callback drains. This is the - // guarantee that OnTimerFired will not dereference `this` after destruction. - if (m_timer) - { - SetThreadpoolTimer(m_timer.get(), nullptr, 0, 0); - WaitForThreadpoolTimerCallbacks(m_timer.get(), TRUE); - } -} - -void CALLBACK WslSlowOperation::OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept -try -{ - auto* self = static_cast(Context); - - WSL_LOG_TELEMETRY( - "SlowOperation", - PDT_ProductAndServicePerformance, - TraceLoggingValue(self->m_name, "name"), - TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs")); - - WSL_LOG( - "SlowOperation", TraceLoggingValue(self->m_name, "name"), TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs")); -} -CATCH_LOG() diff --git a/src/windows/common/WslSlowOperation.h b/src/windows/common/WslSlowOperation.h deleted file mode 100644 index 07bdbab48..000000000 --- a/src/windows/common/WslSlowOperation.h +++ /dev/null @@ -1,53 +0,0 @@ -/*++ - -Copyright (c) Microsoft. All rights reserved. - -Module Name: - - WslSlowOperation.h - -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 destructor cancels 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 plus a matching debug log so the backend can - attribute where time is spent. - - Usage: - - WslSlowOperation slow{"WaitForMiniInitConnect"}; - m_miniInitChannel = wsl::shared::SocketChannel{AcceptConnection(timeout), ...}; - ---*/ - -#pragma once - -#include -#include -#include - -class WslSlowOperation -{ -public: - // Name must have static storage duration (string literal). It is emitted verbatim into - // telemetry and log, so keep it a short CamelCase phase identifier that the backend - // query can switch on (e.g. "WaitForMiniInitConnect"). - explicit WslSlowOperation(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold = std::chrono::seconds{10}); - - ~WslSlowOperation() noexcept; - - WslSlowOperation(const WslSlowOperation&) = delete; - WslSlowOperation& operator=(const WslSlowOperation&) = delete; - WslSlowOperation(WslSlowOperation&&) = delete; - WslSlowOperation& operator=(WslSlowOperation&&) = delete; - -private: - static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept; - - const char* const m_name; - const std::chrono::milliseconds m_slowThreshold; - wil::unique_threadpool_timer m_timer; -}; diff --git a/src/windows/common/precomp.h b/src/windows/common/precomp.h index e3b7a64f8..3f9cb2d9d 100644 --- a/src/windows/common/precomp.h +++ b/src/windows/common/precomp.h @@ -134,7 +134,7 @@ Module Name: // Telemetry Header #include "WslTelemetry.h" -#include "WslSlowOperation.h" +#include "SlowOperationWatcher.h" // LxCore headers #include diff --git a/src/windows/service/exe/PluginManager.cpp b/src/windows/service/exe/PluginManager.cpp index fcd64dc9f..29c39b9e0 100644 --- a/src/windows/service/exe/PluginManager.cpp +++ b/src/windows/service/exe/PluginManager.cpp @@ -181,7 +181,7 @@ void PluginManager::OnVmStarted(const WSLSessionInformation* Session, const WSLV WSL_LOG( "PluginOnVmStartedCall", TraceLoggingValue(e.name.c_str(), "Plugin"), TraceLoggingValue(Session->UserSid, "Sid")); - WslSlowOperation slowOperation{"PluginOnVmStarted"}; + SlowOperationWatcher slowOperation{"PluginOnVmStarted"}; ThrowIfPluginError(e.hooks.OnVMStarted(Session, Settings), Session->SessionId, e.name.c_str()); } } @@ -218,7 +218,7 @@ void PluginManager::OnDistributionStarted(const WSLSessionInformation* Session, TraceLoggingValue(Session->UserSid, "Sid"), TraceLoggingValue(Distribution->Id, "DistributionId")); - WslSlowOperation slowOperation{"PluginOnDistributionStarted"}; + SlowOperationWatcher slowOperation{"PluginOnDistributionStarted"}; ThrowIfPluginError(e.hooks.OnDistributionStarted(Session, Distribution), Session->SessionId, e.name.c_str()); } } diff --git a/src/windows/service/exe/WslCoreInstance.cpp b/src/windows/service/exe/WslCoreInstance.cpp index 5590f8521..3bd416f7f 100644 --- a/src/windows/service/exe/WslCoreInstance.cpp +++ b/src/windows/service/exe/WslCoreInstance.cpp @@ -44,15 +44,12 @@ WslCoreInstance::WslCoreInstance( m_initChannel = std::make_shared(InitSocket.release(), m_runtimeId, m_socketTimeout); // Read a message from the init daemon. This will let us know if anything failed during startup. - // The WslSlowOperation scope is narrowed to the receive so the reported duration reflects the - // wait, not the rest of the constructor. + // The watcher is disarmed as soon as the receive returns so its reported duration reflects + // only the wait, not the rest of the constructor. gsl::span span; - const LX_MINI_INIT_CREATE_INSTANCE_RESULT* resultPtr = nullptr; - { - WslSlowOperation slowOperation{"WaitForCreateInstanceResult"}; - resultPtr = &m_initChannel->GetChannel().ReceiveMessage(&span, m_socketTimeout); - } - const auto& result = *resultPtr; + SlowOperationWatcher slowOperation{"WaitForCreateInstanceResult"}; + const auto& result = m_initChannel->GetChannel().ReceiveMessage(&span, m_socketTimeout); + slowOperation.Reset(); if (result.WarningsOffset != 0) { for (const auto& e : wsl::shared::string::Split(wsl::shared::string::FromSpan(span, result.WarningsOffset), '\n')) @@ -380,7 +377,7 @@ void WslCoreInstance::Initialize() // If drive mounting is supported, ensure that DrvFs has been initialized. if (WI_IsFlagSet(m_configuration.Flags, LXSS_DISTRO_FLAGS_ENABLE_DRIVE_MOUNTING)) { - WslSlowOperation slowOperation{"WaitForDrvFsInit"}; + SlowOperationWatcher slowOperation{"WaitForDrvFsInit"}; drvfsMount = m_initializeDrvFs(m_userToken.get()); } @@ -402,15 +399,12 @@ void WslCoreInstance::Initialize() transaction.Send(gsl::span(config)); // Init replies with information about the distribution. - // The WslSlowOperation scope is narrowed to the receive so the reported duration reflects the - // wait, not the subsequent interop-server launch. + // The watcher is disarmed as soon as the receive returns so its reported duration reflects + // only the wait, not the subsequent interop-server launch. gsl::span span; - const LX_INIT_CONFIGURATION_INFORMATION_RESPONSE* responsePtr = nullptr; - { - WslSlowOperation slowOperation{"WaitForInitConfigResponse"}; - responsePtr = &transaction.Receive(&span); - } - const auto& response = *responsePtr; + SlowOperationWatcher slowOperation{"WaitForInitConfigResponse"}; + const auto& response = transaction.Receive(&span); + slowOperation.Reset(); m_defaultUid = response.DefaultUid; m_plan9Port = response.Plan9Port; m_distributionInfo.PidNamespace = response.PidNamespace; diff --git a/src/windows/service/exe/WslCoreVm.cpp b/src/windows/service/exe/WslCoreVm.cpp index 47bce6033..33a67f651 100644 --- a/src/windows/service/exe/WslCoreVm.cpp +++ b/src/windows/service/exe/WslCoreVm.cpp @@ -322,7 +322,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Create the utility VM and store the runtime ID. std::wstring json = GenerateConfigJson(); { - WslSlowOperation slowOperation{"HcsCreateSystem"}; + SlowOperationWatcher slowOperation{"HcsCreateSystem"}; m_system = wsl::windows::common::hcs::CreateComputeSystem(m_machineId.c_str(), json.c_str()); } m_runtimeId = wsl::windows::common::hcs::GetRuntimeId(m_system.get()); @@ -349,7 +349,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Start the utility VM. try { - WslSlowOperation slowOperation{"HcsStartSystem"}; + SlowOperationWatcher slowOperation{"HcsStartSystem"}; wsl::windows::common::hcs::StartComputeSystem(m_system.get(), json.c_str()); } catch (...) @@ -441,7 +441,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Accept a connection from mini_init with a receive timeout so the service does not get stuck waiting for a response from the VM. { - WslSlowOperation slowOperation{"WaitForMiniInitConnect"}; + SlowOperationWatcher slowOperation{"WaitForMiniInitConnect"}; m_miniInitChannel = wsl::shared::SocketChannel{AcceptConnection(m_vmConfig.KernelBootTimeout), "mini_init", m_terminatingEvent.get()}; } @@ -451,7 +451,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Receive and parse the guest kernel version { - WslSlowOperation slowOperation{"ReadGuestCapabilities"}; + SlowOperationWatcher slowOperation{"ReadGuestCapabilities"}; ReadGuestCapabilities(); } @@ -543,7 +543,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken { ExecutionContext context(Context::ConfigureNetworking); - WslSlowOperation slowOperation{"ConfigureNetworking"}; + SlowOperationWatcher slowOperation{"ConfigureNetworking"}; // Accept the connection from the guest network service and create the channel. wsl::core::GnsChannel gnsChannel(AcceptConnection(m_vmConfig.KernelBootTimeout)); @@ -564,7 +564,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken if (m_vmConfig.NetworkingMode == NetworkingMode::Nat) { { - WslSlowOperation slowOperation{"CreateNatNetwork"}; + SlowOperationWatcher slowOperation{"CreateNatNetwork"}; natNetwork = wsl::core::NatNetworking::CreateNetwork(m_vmConfig); } if (!natNetwork) @@ -676,7 +676,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken // Perform additional initialization. { - WslSlowOperation slowOperation{"InitializeGuest"}; + SlowOperationWatcher slowOperation{"InitializeGuest"}; InitializeGuest(); } } @@ -1188,7 +1188,7 @@ std::shared_ptr WslCoreVm::CreateInstance( auto lock = m_lock.lock_exclusive(); ULONG lun = 0; { - WslSlowOperation slowOperation{"AttachDistroVhd"}; + SlowOperationWatcher slowOperation{"AttachDistroVhd"}; lun = AttachDiskLockHeld(Configuration.VhdFilePath.c_str(), DiskType::VHD, MountFlags::None, {}, false, m_userToken.get()); } @@ -1231,7 +1231,7 @@ std::shared_ptr WslCoreVm::CreateInstance( message.WriteString(message->InstallPathOffset, installPath); message.WriteString(message->UserProfileOffset, userProfile); { - WslSlowOperation slowOperation{"SendLaunchInit"}; + SlowOperationWatcher slowOperation{"SendLaunchInit"}; auto transaction = m_miniInitChannel.StartTransaction(); transaction.Send(message.Span()); } @@ -1259,7 +1259,7 @@ std::shared_ptr WslCoreVm::CreateInstanceInternal( // Establish a communication channel with the init daemon. wil::unique_socket initSocket; { - WslSlowOperation slowOperation{"WaitForInitDaemonConnect"}; + SlowOperationWatcher slowOperation{"WaitForInitDaemonConnect"}; initSocket = AcceptConnection(ReceiveTimeout); } From a94d22069aab6a0288d94859f6c5f15252ebc71e Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Thu, 23 Apr 2026 11:14:10 +0800 Subject: [PATCH 06/10] resolve comments --- src/windows/service/exe/WslCoreVm.cpp | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) diff --git a/src/windows/service/exe/WslCoreVm.cpp b/src/windows/service/exe/WslCoreVm.cpp index 33a67f651..8907c40a3 100644 --- a/src/windows/service/exe/WslCoreVm.cpp +++ b/src/windows/service/exe/WslCoreVm.cpp @@ -1186,11 +1186,9 @@ std::shared_ptr WslCoreVm::CreateInstance( { // Add the VHD to the machine. auto lock = m_lock.lock_exclusive(); - ULONG lun = 0; - { - SlowOperationWatcher slowOperation{"AttachDistroVhd"}; - lun = AttachDiskLockHeld(Configuration.VhdFilePath.c_str(), DiskType::VHD, MountFlags::None, {}, false, m_userToken.get()); - } + SlowOperationWatcher slowOperation{"AttachDistroVhd"}; + const auto lun = AttachDiskLockHeld(Configuration.VhdFilePath.c_str(), DiskType::VHD, MountFlags::None, {}, false, m_userToken.get()); + slowOperation.Reset(); // Launch the init daemon and create the instance. int flags = LxMiniInitMessageFlagNone; @@ -1257,11 +1255,9 @@ std::shared_ptr WslCoreVm::CreateInstanceInternal( WI_ClearFlagIf(localConfig.Flags, LXSS_DISTRO_FLAGS_ENABLE_DRIVE_MOUNTING, !m_vmConfig.EnableHostFileSystemAccess); // Establish a communication channel with the init daemon. - wil::unique_socket initSocket; - { - SlowOperationWatcher slowOperation{"WaitForInitDaemonConnect"}; - initSocket = AcceptConnection(ReceiveTimeout); - } + SlowOperationWatcher slowOperation{"WaitForInitDaemonConnect"}; + auto initSocket = AcceptConnection(ReceiveTimeout); + slowOperation.Reset(); // If the system distro is enabled, establish a communication channel with its init daemon. wil::unique_socket systemDistroSocket; From b62b81da20c61bfef024e0496a71bb0073aab2dc Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Thu, 23 Apr 2026 11:28:51 +0800 Subject: [PATCH 07/10] update --- src/windows/common/SlowOperationWatcher.cpp | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp index 64863657c..dded22bde 100644 --- a/src/windows/common/SlowOperationWatcher.cpp +++ b/src/windows/common/SlowOperationWatcher.cpp @@ -31,6 +31,22 @@ FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept ft.dwHighDateTime = due.HighPart; return ft; } + +// std::source_location::file_name() returns the path as the compiler saw it, which on +// MSVC is an absolute build-agent path. Strip to the basename so telemetry groups the +// same file across different build environments without leaking machine-specific paths. +const char* Basename(const char* Path) noexcept +{ + const char* result = Path; + for (const char* p = Path; *p != '\0'; ++p) + { + if (*p == '\\' || *p == '/') + { + result = p + 1; + } + } + return result; +} } // namespace SlowOperationWatcher::SlowOperationWatcher( @@ -59,7 +75,7 @@ try PDT_ProductAndServicePerformance, TraceLoggingValue(self->m_name, "name"), TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs"), - TraceLoggingValue(self->m_location.file_name(), "file"), + TraceLoggingValue(Basename(self->m_location.file_name()), "file"), TraceLoggingValue(self->m_location.function_name(), "function"), TraceLoggingUInt32(self->m_location.line(), "line")); } From 8fd0c0c589837f3718456cc70cfb83d7f2fb68c8 Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Thu, 23 Apr 2026 11:43:05 +0800 Subject: [PATCH 08/10] format src files --- src/windows/common/SlowOperationWatcher.cpp | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp index dded22bde..1fca45899 100644 --- a/src/windows/common/SlowOperationWatcher.cpp +++ b/src/windows/common/SlowOperationWatcher.cpp @@ -49,8 +49,7 @@ const char* Basename(const char* Path) noexcept } } // namespace -SlowOperationWatcher::SlowOperationWatcher( - _In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location) : +SlowOperationWatcher::SlowOperationWatcher(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location) : m_name(Name), m_slowThreshold(SlowThreshold), m_location(Location) { m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); From d83bd7ede5c39db2eddccd0f5fb6b59c16a94ee3 Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Thu, 23 Apr 2026 12:11:25 +0800 Subject: [PATCH 09/10] resolve comments --- src/windows/common/SlowOperationWatcher.cpp | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp index 1fca45899..ea90a055a 100644 --- a/src/windows/common/SlowOperationWatcher.cpp +++ b/src/windows/common/SlowOperationWatcher.cpp @@ -23,13 +23,9 @@ Module Name: namespace { FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept { - // Negative FILETIME means "relative to now", in 100ns units. - ULARGE_INTEGER due{}; - due.QuadPart = static_cast(-(Relative.count() * 10'000LL)); - FILETIME ft{}; - ft.dwLowDateTime = due.LowPart; - ft.dwHighDateTime = due.HighPart; - return ft; + // Negative FILETIME means "relative to now", in 100ns units. Matches the pattern used + // elsewhere in the service (see Lifetime.cpp). + return wil::filetime::from_int64(-wil::filetime_duration::one_millisecond * Relative.count()); } // std::source_location::file_name() returns the path as the compiler saw it, which on @@ -53,7 +49,7 @@ SlowOperationWatcher::SlowOperationWatcher(_In_z_ const char* Name, std::chrono: m_name(Name), m_slowThreshold(SlowThreshold), m_location(Location) { m_timer.reset(CreateThreadpoolTimer(OnTimerFired, this, nullptr)); - THROW_LAST_ERROR_IF_NULL(m_timer.get()); + THROW_IF_NULL_ALLOC(m_timer.get()); FILETIME due = RelativeFileTime(m_slowThreshold); SetThreadpoolTimer(m_timer.get(), &due, 0, 0); From 9e65c780657a6cbd1e68e034f8e17477554dd2f9 Mon Sep 17 00:00:00 2001 From: Shawn Yuan Date: Fri, 24 Apr 2026 09:26:50 +0800 Subject: [PATCH 10/10] resolve comments --- src/windows/common/SlowOperationWatcher.cpp | 21 ++++++++++----------- src/windows/common/SlowOperationWatcher.h | 18 +++++++++++++----- src/windows/service/exe/WslCoreVm.cpp | 13 +++---------- 3 files changed, 26 insertions(+), 26 deletions(-) diff --git a/src/windows/common/SlowOperationWatcher.cpp b/src/windows/common/SlowOperationWatcher.cpp index ea90a055a..e08a51591 100644 --- a/src/windows/common/SlowOperationWatcher.cpp +++ b/src/windows/common/SlowOperationWatcher.cpp @@ -31,18 +31,17 @@ FILETIME RelativeFileTime(std::chrono::milliseconds Relative) noexcept // std::source_location::file_name() returns the path as the compiler saw it, which on // MSVC is an absolute build-agent path. Strip to the basename so telemetry groups the // same file across different build environments without leaking machine-specific paths. -const char* Basename(const char* Path) noexcept +// The substring is taken from the same null-terminated char array, so the returned view's +// data() is safe to pass to C APIs that expect a null-terminated string. +constexpr std::string_view Basename(std::string_view Path) noexcept { - const char* result = Path; - for (const char* p = Path; *p != '\0'; ++p) - { - if (*p == '\\' || *p == '/') - { - result = p + 1; - } - } - return result; + const auto pos = Path.find_last_of("\\/"); + return pos == std::string_view::npos ? Path : Path.substr(pos + 1); } + +static_assert(Basename("/foo/bar/test.cpp") == "test.cpp"); +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) : @@ -70,7 +69,7 @@ try PDT_ProductAndServicePerformance, TraceLoggingValue(self->m_name, "name"), TraceLoggingInt64(self->m_slowThreshold.count(), "thresholdMs"), - TraceLoggingValue(Basename(self->m_location.file_name()), "file"), + TraceLoggingValue(Basename(self->m_location.file_name()).data(), "file"), TraceLoggingValue(self->m_location.function_name(), "function"), TraceLoggingUInt32(self->m_location.line(), "line")); } diff --git a/src/windows/common/SlowOperationWatcher.h b/src/windows/common/SlowOperationWatcher.h index 4780a5ade..55b86c637 100644 --- a/src/windows/common/SlowOperationWatcher.h +++ b/src/windows/common/SlowOperationWatcher.h @@ -43,13 +43,19 @@ Module Name: class SlowOperationWatcher { public: - // Name must have static storage duration (string literal). It is emitted verbatim into - // telemetry, so keep it a short CamelCase phase identifier that the backend query can - // switch on (e.g. "WaitForMiniInitConnect"). + // 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"). + template explicit SlowOperationWatcher( - _In_z_ const char* Name, + const char (&Name)[N], std::chrono::milliseconds SlowThreshold = std::chrono::seconds{10}, - std::source_location Location = std::source_location::current()); + std::source_location Location = std::source_location::current()) : + SlowOperationWatcher(static_cast(Name), SlowThreshold, Location) + { + } ~SlowOperationWatcher() noexcept = default; @@ -64,6 +70,8 @@ class SlowOperationWatcher SlowOperationWatcher& operator=(SlowOperationWatcher&&) = delete; private: + explicit SlowOperationWatcher(_In_z_ const char* Name, std::chrono::milliseconds SlowThreshold, std::source_location Location); + static void CALLBACK OnTimerFired(PTP_CALLBACK_INSTANCE, PVOID Context, PTP_TIMER) noexcept; const char* const m_name; diff --git a/src/windows/service/exe/WslCoreVm.cpp b/src/windows/service/exe/WslCoreVm.cpp index c58ba937e..907adf151 100644 --- a/src/windows/service/exe/WslCoreVm.cpp +++ b/src/windows/service/exe/WslCoreVm.cpp @@ -543,7 +543,6 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken { ExecutionContext context(Context::ConfigureNetworking); - SlowOperationWatcher slowOperation{"ConfigureNetworking"}; // Accept the connection from the guest network service and create the channel. wsl::core::GnsChannel gnsChannel(AcceptConnection(m_vmConfig.KernelBootTimeout)); @@ -675,10 +674,7 @@ void WslCoreVm::Initialize(const GUID& VmId, const wil::shared_handle& UserToken } // Perform additional initialization. - { - SlowOperationWatcher slowOperation{"InitializeGuest"}; - InitializeGuest(); - } + InitializeGuest(); } WslCoreVm::~WslCoreVm() noexcept @@ -1237,11 +1233,8 @@ std::shared_ptr WslCoreVm::CreateInstance( message.WriteString(message->SharedMemoryRootOffset, sharedMemoryRoot); message.WriteString(message->InstallPathOffset, installPath); message.WriteString(message->UserProfileOffset, userProfile); - { - SlowOperationWatcher slowOperation{"SendLaunchInit"}; - auto transaction = m_miniInitChannel.StartTransaction(); - transaction.Send(message.Span()); - } + auto transaction = m_miniInitChannel.StartTransaction(); + transaction.Send(message.Span()); return CreateInstanceInternal( InstanceId, Configuration, ReceiveTimeout, DefaultUid, ClientLifetimeId, WI_IsFlagSet(flags, LxMiniInitMessageFlagLaunchSystemDistro), ConnectPort);