| 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() |