From 9838b6911b163af02e04722dea30c0a92be7e9dd Mon Sep 17 00:00:00 2001 From: "Taylor, Raymond" Date: Thu, 4 Jun 2026 15:59:25 -0700 Subject: [PATCH 1/5] default to Sleep for interval waiter, no spin phase --- .../AppCef/ipm-ui-vue/src/core/preferences.ts | 14 ++++- .../CommonUtilities/IntervalWaiter.cpp | 52 +++++++++++++++++-- .../CommonUtilities/IntervalWaiter.h | 21 +++++++- .../CommonUtilities/PrecisionWaiter.cpp | 6 ++- .../PresentMonService/PMMainThread.cpp | 2 +- IntelPresentMon/UnitTests/Timing.cpp | 10 +++- 6 files changed, 92 insertions(+), 13 deletions(-) diff --git a/IntelPresentMon/AppCef/ipm-ui-vue/src/core/preferences.ts b/IntelPresentMon/AppCef/ipm-ui-vue/src/core/preferences.ts index 4783d43b..9231712f 100644 --- a/IntelPresentMon/AppCef/ipm-ui-vue/src/core/preferences.ts +++ b/IntelPresentMon/AppCef/ipm-ui-vue/src/core/preferences.ts @@ -81,7 +81,7 @@ export function makeDefaultPreferences(): Preferences { telemetrySamplingPeriodMs: 100, etwFlushPeriod: 8, manualEtwFlush: true, - metricsOffset: 80, + metricsOffset: 150, metricsWindow: 1000, overlayPosition: 0, timeRange: 10, @@ -140,7 +140,7 @@ export function makeDefaultPreferences(): Preferences { export const signature: Signature = { code: "p2c-cap-pref", - version: "0.20.0", + version: "0.21.0", }; export interface PreferenceFile { @@ -207,6 +207,16 @@ const migrations: Migration[] = [ } } }, + { + version: '0.21.0', + migrate: (prefs: Preferences) => { + if (prefs.metricsOffset === 80) { + const def = makeDefaultPreferences(); + console.info(`Migrating preferences to 0.21.0 (metricsOffset: ${prefs.metricsOffset} => ${def.metricsOffset})`); + prefs.metricsOffset = def.metricsOffset; + } + } + }, ]; migrations.sort((a, b) => compareVersions(a.version, b.version)); diff --git a/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp b/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp index 63749420..73e4fef3 100644 --- a/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp +++ b/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp @@ -1,19 +1,39 @@ #include "IntervalWaiter.h" +#include "win/WinAPI.h" +#include #include namespace pmon::util { - IntervalWaiter::IntervalWaiter(double intervalSeconds, int64_t syncTimestamp, double waitBuffer) + IntervalWaiter::IntervalWaiter(double intervalSeconds, int64_t syncTimestamp, Options options) : intervalSeconds_{ intervalSeconds }, - waiter_{ waitBuffer }, + options_{ options }, + waiter_{ options.spinBufferSeconds }, timer_{ syncTimestamp } {} - IntervalWaiter::IntervalWaiter(double intervalSeconds, double waitBuffer) + IntervalWaiter::IntervalWaiter(double intervalSeconds, Options options) : intervalSeconds_{ intervalSeconds }, - waiter_{ waitBuffer } + options_{ options }, + waiter_{ options.spinBufferSeconds } + {} + + IntervalWaiter::IntervalWaiter(double intervalSeconds, int64_t syncTimestamp, double waitBuffer) + : + IntervalWaiter{ intervalSeconds, syncTimestamp, Options{ + .mechanism = WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = waitBuffer, + } } + {} + + IntervalWaiter::IntervalWaiter(double intervalSeconds, double waitBuffer) + : + IntervalWaiter{ intervalSeconds, Options{ + .mechanism = WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = waitBuffer, + } } {} void IntervalWaiter::SetInterval(double intervalSeconds) @@ -26,6 +46,16 @@ namespace pmon::util intervalSeconds_ = double(interval.count()) / 1'000'000'000.; } + void IntervalWaiter::SetOptions(Options options) + { + options_ = options; + } + + IntervalWaiter::Options IntervalWaiter::GetOptions() const + { + return options_; + } + IntervalWaiter::WaitResult IntervalWaiter::Wait() { WaitResult res{}; @@ -43,7 +73,7 @@ namespace pmon::util return 0.; }(); if (waitTimeSeconds > 0.) { - res.errorSec = waiter_.Wait(waitTimeSeconds); + res.errorSec = WaitFor(waitTimeSeconds); } return res; } @@ -52,4 +82,16 @@ namespace pmon::util { return timer_.TimeToTimestamp(targetTime); } + + double IntervalWaiter::WaitFor(double seconds) + { + switch (options_.mechanism) { + case WaitMechanism::HighPrecisionTimer: + return waiter_.WaitWithBuffer(seconds, options_.spinBufferSeconds); + case WaitMechanism::Sleep: + default: + Sleep((DWORD)std::ceil(seconds * 1000.)); + return 0.; + } + } } diff --git a/IntelPresentMon/CommonUtilities/IntervalWaiter.h b/IntelPresentMon/CommonUtilities/IntervalWaiter.h index 40b18c55..462c03d7 100644 --- a/IntelPresentMon/CommonUtilities/IntervalWaiter.h +++ b/IntelPresentMon/CommonUtilities/IntervalWaiter.h @@ -7,6 +7,12 @@ namespace pmon::util { + enum class WaitMechanism + { + Sleep, + HighPrecisionTimer, + }; + class IntervalWaiter { public: @@ -16,9 +22,16 @@ namespace pmon::util double targetSec; double errorSec; }; + struct Options + { + WaitMechanism mechanism = WaitMechanism::Sleep; + double spinBufferSeconds = 0.; + }; // functions - IntervalWaiter(double intervalSeconds, int64_t syncTimestamp, double waitBuffer = PrecisionWaiter::standardWaitBuffer); - IntervalWaiter(double intervalSeconds, double waitBuffer = PrecisionWaiter::standardWaitBuffer); + IntervalWaiter(double intervalSeconds, int64_t syncTimestamp, Options options = {}); + IntervalWaiter(double intervalSeconds, Options options = {}); + IntervalWaiter(double intervalSeconds, int64_t syncTimestamp, double waitBuffer); + IntervalWaiter(double intervalSeconds, double waitBuffer); IntervalWaiter(const IntervalWaiter&) = delete; IntervalWaiter & operator=(const IntervalWaiter&) = delete; IntervalWaiter(IntervalWaiter&&) = delete; @@ -26,11 +39,15 @@ namespace pmon::util ~IntervalWaiter() = default; void SetInterval(double intervalSeconds); void SetInterval(std::chrono::nanoseconds interval); + void SetOptions(Options options); + Options GetOptions() const; WaitResult Wait(); int64_t TargetTimeToTimestamp(double targetTime) const; private: + double WaitFor(double seconds); double intervalSeconds_; double lastTargetTime_ = 0.; + Options options_; PrecisionWaiter waiter_; QpcTimer timer_; }; diff --git a/IntelPresentMon/CommonUtilities/PrecisionWaiter.cpp b/IntelPresentMon/CommonUtilities/PrecisionWaiter.cpp index 2429b68a..73c59558 100644 --- a/IntelPresentMon/CommonUtilities/PrecisionWaiter.cpp +++ b/IntelPresentMon/CommonUtilities/PrecisionWaiter.cpp @@ -3,6 +3,7 @@ #include "win/WinAPI.h" #include "Exception.h" #include "PrecisionWaiter.h" +#include namespace pmon::util @@ -38,10 +39,13 @@ namespace pmon::util // mark the start time of the wait if we're doing buffer with precision spin if (buffer > 0.) { qpcTimer_.Mark(); + if (seconds <= buffer) { + return qpcTimer_.SpinWaitUntil(seconds); + } } // wait slightly (buffer seconds) shorter than required to compensate for overwait error const LARGE_INTEGER waitTime100ns{ - .QuadPart = -LONGLONG(double(seconds - defaultWaitBuffer_) * 10'000'000.) + .QuadPart = -LONGLONG(std::max(seconds - buffer, 0.) * 10'000'000.) }; // set the timer deadline if (!SetWaitableTimerEx( diff --git a/IntelPresentMon/PresentMonService/PMMainThread.cpp b/IntelPresentMon/PresentMonService/PMMainThread.cpp index b2bee217..b9eb5f55 100644 --- a/IntelPresentMon/PresentMonService/PMMainThread.cpp +++ b/IntelPresentMon/PresentMonService/PMMainThread.cpp @@ -134,7 +134,7 @@ void TelemetryThreadEntry_(Service* const srv, PresentMon* const pm, ipc::Servic "Finished populating telemetry introspection, {} seconds elapsed", timer.Mark())); - IntervalWaiter waiter{ 0.016 }; + IntervalWaiter waiter{ 0.1 }; while (true) { pmlog_dbg("(re)starting telemetry idle wait"); if (WaitAnyEvent(pm->GetDeviceUsageEvent(), srv->GetServiceStopHandle()) == 1) { diff --git a/IntelPresentMon/UnitTests/Timing.cpp b/IntelPresentMon/UnitTests/Timing.cpp index 8a1b8f3c..501c8f1a 100644 --- a/IntelPresentMon/UnitTests/Timing.cpp +++ b/IntelPresentMon/UnitTests/Timing.cpp @@ -300,7 +300,10 @@ namespace UtilityTests constexpr auto workMillis = 16; constexpr auto singleErrorThreshold = 0.000'180; constexpr auto aggregateErrorThresholdPerIteration = 0.000'070; - util::IntervalWaiter waiter{ waitInterval }; + util::IntervalWaiter waiter{ waitInterval, util::IntervalWaiter::Options{ + .mechanism = util::WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = util::PrecisionWaiter::standardWaitBuffer, + } }; RunWaitAccuracyTest(L"IntervalWaiterChrono", waitInterval, iterations, singleErrorThreshold, aggregateErrorThresholdPerIteration, [&]() { Sleep(workMillis); waiter.Wait(); @@ -326,7 +329,10 @@ namespace UtilityTests double totalOnTimeCadenceSeconds = 0.; double aggregateOnTimeCadenceError = 0.; int onTimeIterations = 0; - util::IntervalWaiter waiter{ waitInterval }; + util::IntervalWaiter waiter{ waitInterval, util::IntervalWaiter::Options{ + .mechanism = util::WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = util::PrecisionWaiter::standardWaitBuffer, + } }; util::QpcTimer iterationTimer; util::QpcTimer workTimer; util::QpcTimer waitTimer; From f68964f324ac18fe0ff0563802f8650bbb26ca20 Mon Sep 17 00:00:00 2001 From: "Taylor, Raymond" Date: Thu, 4 Jun 2026 16:20:52 -0700 Subject: [PATCH 2/5] keep sampling window placement precise even when interval timer misses --- .../Core/source/kernel/MetricPackMapper.h | 10 ++++++---- IntelPresentMon/Core/source/kernel/Overlay.cpp | 7 ++++--- IntelPresentMon/Core/source/kernel/Overlay.h | 2 +- IntelPresentMon/Core/source/pmon/DynamicQuery.cpp | 12 +++++++++++- IntelPresentMon/Core/source/pmon/DynamicQuery.h | 3 ++- 5 files changed, 24 insertions(+), 10 deletions(-) diff --git a/IntelPresentMon/Core/source/kernel/MetricPackMapper.h b/IntelPresentMon/Core/source/kernel/MetricPackMapper.h index e7bf95f1..20b65d51 100644 --- a/IntelPresentMon/Core/source/kernel/MetricPackMapper.h +++ b/IntelPresentMon/Core/source/kernel/MetricPackMapper.h @@ -2,6 +2,7 @@ #include "DataFetchPack.h" #include "../pmon/MetricFetcherFactory.h" #include "../pmon/DynamicQuery.h" +#include "../pmon/Timekeeper.h" #include "../infra/Logging.h" #include "OverlaySpec.h" #include @@ -100,13 +101,14 @@ namespace p2c::kern } usageMap_[qmet].text = true; } - void Populate(const pmapi::ProcessTracker& tracker, double timestamp) + void Populate(const pmapi::ProcessTracker& tracker, uint64_t timestamp) { // if query is empty, don't do anything (empty loadout) if (pQuery_) { - pQuery_->Poll(tracker); + pQuery_->PollWithTimestamp(tracker, timestamp); + const auto time = pmon::Timekeeper::RelativeToEpoch((int64_t)timestamp); for (auto&& [qmet, pPack] : metricPackMap_) { - pPack.Populate(timestamp); + pPack.Populate(time); } } } @@ -129,4 +131,4 @@ namespace p2c::kern // i.e. which ones can carry over, differentiates between graph and readout std::unordered_map usageMap_; }; -} \ No newline at end of file +} diff --git a/IntelPresentMon/Core/source/kernel/Overlay.cpp b/IntelPresentMon/Core/source/kernel/Overlay.cpp index f31dd0b1..f02b1105 100644 --- a/IntelPresentMon/Core/source/kernel/Overlay.cpp +++ b/IntelPresentMon/Core/source/kernel/Overlay.cpp @@ -270,7 +270,7 @@ namespace p2c::kern } } - void Overlay::UpdateGraphData_(double timestamp) + void Overlay::UpdateGraphData_(uint64_t timestamp) { if (!IsTargetLive()) { pmlog_dbg("Target found dead") @@ -429,12 +429,13 @@ namespace p2c::kern { const auto wait = scheduler_.GetNextWait(); samplingWaiter.SetInterval(wait); - samplingWaiter.Wait(); + const auto waitResult = samplingWaiter.Wait(); + const auto targetTimestamp = samplingWaiter.TargetTimeToTimestamp(waitResult.targetSec); pmon::Timekeeper::LockNow(); if (scheduler_.AtPoll() && !IsHidden_()) { pmlog_mark mkPoll; - UpdateGraphData_(pmon::Timekeeper::GetLockedNow()); + UpdateGraphData_((uint64_t)targetTimestamp); pmlog_perf(clog::p::overlay)("Data update time").mark(mkPoll); } if (scheduler_.AtRender()) { diff --git a/IntelPresentMon/Core/source/kernel/Overlay.h b/IntelPresentMon/Core/source/kernel/Overlay.h index 851de96a..68a6895b 100644 --- a/IntelPresentMon/Core/source/kernel/Overlay.h +++ b/IntelPresentMon/Core/source/kernel/Overlay.h @@ -63,7 +63,7 @@ namespace p2c::kern private: // functions void AdjustOverlaySituation_(OverlaySpec::OverlayPosition position); - void UpdateGraphData_(double timestamp); + void UpdateGraphData_(uint64_t timestamp); void Render_(); void UpdateCaptureStatusText_(); void UpdateDataSets_(); diff --git a/IntelPresentMon/Core/source/pmon/DynamicQuery.cpp b/IntelPresentMon/Core/source/pmon/DynamicQuery.cpp index ac0a5089..94f6639f 100644 --- a/IntelPresentMon/Core/source/pmon/DynamicQuery.cpp +++ b/IntelPresentMon/Core/source/pmon/DynamicQuery.cpp @@ -35,6 +35,16 @@ namespace p2c::pmon } } + void DynamicQuery::PollWithTimestamp(const pmapi::ProcessTracker& tracker, uint64_t nowTimestamp) + { + if (query) { + query.PollWithTimestamp(tracker, blobs, nowTimestamp); + } + else { + pmlog_warn("Polling empty dynamic query"); + } + } + const uint8_t* DynamicQuery::GetBlobData() const { if (blobs.GetNumBlobsPopulated() == 0) { @@ -42,4 +52,4 @@ namespace p2c::pmon } return blobs.GetFirst(); } -} \ No newline at end of file +} diff --git a/IntelPresentMon/Core/source/pmon/DynamicQuery.h b/IntelPresentMon/Core/source/pmon/DynamicQuery.h index e803b28c..18d54820 100644 --- a/IntelPresentMon/Core/source/pmon/DynamicQuery.h +++ b/IntelPresentMon/Core/source/pmon/DynamicQuery.h @@ -21,6 +21,7 @@ namespace p2c::pmon public: DynamicQuery(pmapi::Session& session, double winSizeMs, double metricOffsetMs, std::span qmet); void Poll(const pmapi::ProcessTracker& tracker); + void PollWithTimestamp(const pmapi::ProcessTracker& tracker, uint64_t nowTimestamp); const uint8_t* GetBlobData() const; std::vector ExtractElements(); private: @@ -28,4 +29,4 @@ namespace p2c::pmon std::vector elements; pmapi::BlobContainer blobs; }; -} \ No newline at end of file +} From 6e7d365102a90b19c6d2922b679be11166208309 Mon Sep 17 00:00:00 2001 From: "Taylor, Raymond" Date: Thu, 4 Jun 2026 17:02:16 -0700 Subject: [PATCH 3/5] change period range and loosen strictness --- .../PresentMonAPI2/PresentMonAPI.h | 3 +- .../InterimBroadcasterTests.cpp | 4 +- .../PresentMonAPI2Tests/MultiClientTests.cpp | 49 ++++++++++++------- .../acts/SetEtwFlushPeriod.h | 20 +++++--- .../acts/SetTelemetryPeriod.h | 22 +++++---- 5 files changed, 60 insertions(+), 38 deletions(-) diff --git a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h index 8fc715fd..a14566db 100644 --- a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h +++ b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h @@ -423,11 +423,12 @@ extern "C" { PRESENTMON_API2_EXPORT PM_STATUS pmFreeIntrospectionRoot(const PM_INTROSPECTION_ROOT* pRoot); // sets the rate at which hardware telemetry (including CPU) is polled PRESENTMON_API2_EXPORT PM_STATUS pmSetTelemetryPollingPeriod(PM_SESSION_HANDLE handle, uint32_t reserved, uint32_t timeMs); -#define PM_TELEMETRY_PERIOD_MIN 4 +#define PM_TELEMETRY_PERIOD_MIN 50 #define PM_TELEMETRY_PERIOD_MAX 5000 // sets the rate at which ETW event buffers are flushed, affecting the delay of frame data reported by PresentMon // a value of zero indicates to use current service setting (default or value requested by other client) PRESENTMON_API2_EXPORT PM_STATUS pmSetEtwFlushPeriod(PM_SESSION_HANDLE handle, uint32_t periodMs); +#define PM_ETW_FLUSH_PERIOD_MIN 8 #define PM_ETW_FLUSH_PERIOD_MAX 1000 // flush any buffered frame event data for the specified process on this session PRESENTMON_API2_EXPORT PM_STATUS pmFlushFrames(PM_SESSION_HANDLE handle, uint32_t processId); diff --git a/IntelPresentMon/PresentMonAPI2Tests/InterimBroadcasterTests.cpp b/IntelPresentMon/PresentMonAPI2Tests/InterimBroadcasterTests.cpp index 0d8bad8b..e0d26d77 100644 --- a/IntelPresentMon/PresentMonAPI2Tests/InterimBroadcasterTests.cpp +++ b/IntelPresentMon/PresentMonAPI2Tests/InterimBroadcasterTests.cpp @@ -371,7 +371,7 @@ namespace InterimBroadcasterTests auto pMetricMap = pmapi::EnumMap::GetKeyMap(PM_ENUM_METRIC); // set telemetry period so we have a known baseline - client.DispatchSync(svc::acts::SetTelemetryPeriod::Params{ .telemetrySamplePeriodMs = 40 }); + client.DispatchSync(svc::acts::SetTelemetryPeriod::Params{ .telemetrySamplePeriodMs = 50 }); // get the store containing adapter telemetry auto& sys = pComms->GetSystemDataStore(); @@ -625,7 +625,7 @@ namespace InterimBroadcasterTests auto pMetricMap = pmapi::EnumMap::GetKeyMap(PM_ENUM_METRIC); // set telemetry period so we have a known baseline - client.DispatchSync(svc::acts::SetTelemetryPeriod::Params{ .telemetrySamplePeriodMs = 40 }); + client.DispatchSync(svc::acts::SetTelemetryPeriod::Params{ .telemetrySamplePeriodMs = 50 }); // target gpu device 1 (hardcoded for test) const uint32_t TargetDeviceID = 1; diff --git a/IntelPresentMon/PresentMonAPI2Tests/MultiClientTests.cpp b/IntelPresentMon/PresentMonAPI2Tests/MultiClientTests.cpp index 87c70d73..e9ef2351 100644 --- a/IntelPresentMon/PresentMonAPI2Tests/MultiClientTests.cpp +++ b/IntelPresentMon/PresentMonAPI2Tests/MultiClientTests.cpp @@ -155,12 +155,12 @@ namespace MultiClientTests // launch a client auto client2 = fixture_.LaunchClient({ - "--telemetry-period-ms"s, "36"s, + "--telemetry-period-ms"s, "50"s, }); // check that telemetry period has been overrided { const auto status = fixture_.service->QueryStatus(); - Assert::AreEqual(36u, status.telemetryPeriodMs); + Assert::AreEqual(50u, status.telemetryPeriodMs); } } // two client test, verify override and then reversion when clients disconnect @@ -178,12 +178,12 @@ namespace MultiClientTests // launch a client auto client2 = fixture_.LaunchClient({ - "--telemetry-period-ms"s, "36"s, + "--telemetry-period-ms"s, "50"s, }); // check that telemetry period has been overrided { const auto status = fixture_.service->QueryStatus(); - Assert::AreEqual(36u, status.telemetryPeriodMs); + Assert::AreEqual(50u, status.telemetryPeriodMs); } // kill client 2 @@ -217,12 +217,12 @@ namespace MultiClientTests // launch a client auto client2 = fixture_.LaunchClient({ - "--telemetry-period-ms"s, "36"s, + "--telemetry-period-ms"s, "50"s, }); // check that telemetry period has been overrided { const auto status = fixture_.service->QueryStatus(); - Assert::AreEqual(36u, status.telemetryPeriodMs); + Assert::AreEqual(50u, status.telemetryPeriodMs); } // murder client 2 @@ -247,27 +247,27 @@ namespace MultiClientTests Assert::AreEqual(16u, status.telemetryPeriodMs); } } - // verify range check error low + // verify out-of-range low clamps instead of failing TEST_METHOD(OutOfRangeLow) { // launch a client auto client = fixture_.LaunchClient({ "--telemetry-period-ms"s, "3"s, - "--test-expect-error"s, }); - // check for expected error - Assert::AreEqual("err-check-ok:PM_STATUS_OUT_OF_RANGE"s, client.Command("err-check")); + // check that telemetry period has been clamped + const auto status = fixture_.service->QueryStatus(); + Assert::AreEqual(50u, status.telemetryPeriodMs); } - // verify range check error high + // verify out-of-range high clamps instead of failing TEST_METHOD(OutOfRangeHigh) { // launch a client auto client = fixture_.LaunchClient({ "--telemetry-period-ms"s, "6000"s, - "--test-expect-error"s, }); - // check for expected error - Assert::AreEqual("err-check-ok:PM_STATUS_OUT_OF_RANGE"s, client.Command("err-check")); + // check that telemetry period has been clamped + const auto status = fixture_.service->QueryStatus(); + Assert::AreEqual(5000u, status.telemetryPeriodMs); } }; @@ -432,16 +432,29 @@ namespace MultiClientTests Assert::IsFalse((bool)status.etwFlushPeriodMs); } } - // verify range check error high + // verify out-of-range high clamps instead of failing TEST_METHOD(OutOfRangeHigh) { // launch a client auto client = fixture_.LaunchClient({ "--etw-flush-period-ms"s, "1500"s, - "--test-expect-error"s, }); - // check for expected error - Assert::AreEqual("err-check-ok:PM_STATUS_OUT_OF_RANGE"s, client.Command("err-check")); + // check that flush period has been clamped + const auto status = fixture_.service->QueryStatus(); + Assert::IsTrue((bool)status.etwFlushPeriodMs); + Assert::AreEqual(1000u, *status.etwFlushPeriodMs); + } + // verify out-of-range low clamps instead of failing + TEST_METHOD(OutOfRangeLow) + { + // launch a client + auto client = fixture_.LaunchClient({ + "--etw-flush-period-ms"s, "7"s, + }); + // check that flush period has been clamped + const auto status = fixture_.service->QueryStatus(); + Assert::IsTrue((bool)status.etwFlushPeriodMs); + Assert::AreEqual(8u, *status.etwFlushPeriodMs); } }; diff --git a/IntelPresentMon/PresentMonService/acts/SetEtwFlushPeriod.h b/IntelPresentMon/PresentMonService/acts/SetEtwFlushPeriod.h index ca94f051..115796bd 100644 --- a/IntelPresentMon/PresentMonService/acts/SetEtwFlushPeriod.h +++ b/IntelPresentMon/PresentMonService/acts/SetEtwFlushPeriod.h @@ -32,15 +32,21 @@ namespace pmon::svc::acts friend class ACT_TYPE; static Response Execute_(const ACT_EXEC_CTX& ctx, SessionContext& stx, Params&& in) { - if (in.etwFlushPeriodMs && *in.etwFlushPeriodMs > PM_ETW_FLUSH_PERIOD_MAX) { - const auto sta = PM_STATUS::PM_STATUS_OUT_OF_RANGE; - pmlog_error("Set ETW flush period failed: out of range").pmwatch(*in.etwFlushPeriodMs).code(sta); - throw util::Except(sta); + auto etwFlushPeriodMs = in.etwFlushPeriodMs; + if (etwFlushPeriodMs && *etwFlushPeriodMs < PM_ETW_FLUSH_PERIOD_MIN) { + pmlog_warn("ETW flush period out of range; clamping to minimum") + .pmwatch(*etwFlushPeriodMs).pmwatch(PM_ETW_FLUSH_PERIOD_MIN).diag(); + etwFlushPeriodMs = PM_ETW_FLUSH_PERIOD_MIN; } - stx.requestedEtwFlushPeriodMs = in.etwFlushPeriodMs; + else if (etwFlushPeriodMs && *etwFlushPeriodMs > PM_ETW_FLUSH_PERIOD_MAX) { + pmlog_warn("ETW flush period out of range; clamping to maximum") + .pmwatch(*etwFlushPeriodMs).pmwatch(PM_ETW_FLUSH_PERIOD_MAX).diag(); + etwFlushPeriodMs = PM_ETW_FLUSH_PERIOD_MAX; + } + stx.requestedEtwFlushPeriodMs = etwFlushPeriodMs; ctx.UpdateEtwFlushPeriod(); - if (in.etwFlushPeriodMs) { - pmlog_dbg(std::format("Setting ETW flush period to {}ms", *in.etwFlushPeriodMs)); + if (etwFlushPeriodMs) { + pmlog_dbg(std::format("Setting ETW flush period to {}ms", *etwFlushPeriodMs)); } else { pmlog_dbg("Disabling manual ETW flush"); diff --git a/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h b/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h index 2c77eb25..75c6b2d4 100644 --- a/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h +++ b/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h @@ -32,22 +32,24 @@ namespace pmon::svc::acts friend class ACT_TYPE; static Response Execute_(const ACT_EXEC_CTX& ctx, SessionContext& stx, Params&& in) { - // make sure requested period is within allowed range - if (in.telemetrySamplePeriodMs) { - if (in.telemetrySamplePeriodMs < PM_TELEMETRY_PERIOD_MIN || - in.telemetrySamplePeriodMs > PM_TELEMETRY_PERIOD_MAX) { - const auto sta = PM_STATUS::PM_STATUS_OUT_OF_RANGE; - pmlog_error("Set telemetry period failed").pmwatch(in.telemetrySamplePeriodMs).code(sta); - throw util::Except(sta); - } + auto telemetrySamplePeriodMs = in.telemetrySamplePeriodMs; + if (telemetrySamplePeriodMs && telemetrySamplePeriodMs < PM_TELEMETRY_PERIOD_MIN) { + pmlog_warn("Telemetry period out of range; clamping to minimum") + .pmwatch(telemetrySamplePeriodMs).pmwatch(PM_TELEMETRY_PERIOD_MIN).diag(); + telemetrySamplePeriodMs = PM_TELEMETRY_PERIOD_MIN; + } + else if (telemetrySamplePeriodMs > PM_TELEMETRY_PERIOD_MAX) { + pmlog_warn("Telemetry period out of range; clamping to maximum") + .pmwatch(telemetrySamplePeriodMs).pmwatch(PM_TELEMETRY_PERIOD_MAX).diag(); + telemetrySamplePeriodMs = PM_TELEMETRY_PERIOD_MAX; } // set request for this session - stx.requestedTelemetryPeriodMs = in.telemetrySamplePeriodMs; + stx.requestedTelemetryPeriodMs = telemetrySamplePeriodMs; // update the service ctx.UpdateTelemetryPeriod(); pmlog_dbg(std::format("Requested telemetry sample period of {}ms by client [{}]", - in.telemetrySamplePeriodMs, stx.remotePid)); + telemetrySamplePeriodMs, stx.remotePid)); return {}; } }; From 7221c45a94c99eeb5ae1e092190725d512e76c11 Mon Sep 17 00:00:00 2001 From: "Taylor, Raymond" Date: Thu, 4 Jun 2026 17:58:45 -0700 Subject: [PATCH 4/5] name service work threads --- IntelPresentMon/PresentMonService/MockPresentMonSession.cpp | 3 +++ IntelPresentMon/PresentMonService/PMMainThread.cpp | 2 ++ .../PresentMonService/RealtimePresentMonSession.cpp | 3 +++ 3 files changed, 8 insertions(+) diff --git a/IntelPresentMon/PresentMonService/MockPresentMonSession.cpp b/IntelPresentMon/PresentMonService/MockPresentMonSession.cpp index eda679e0..4fffa5f0 100644 --- a/IntelPresentMon/PresentMonService/MockPresentMonSession.cpp +++ b/IntelPresentMon/PresentMonService/MockPresentMonSession.cpp @@ -4,6 +4,7 @@ #include "CliOptions.h" #include "..\CommonUtilities\str\String.h" #include "Logging.h" +#include "../CommonUtilities/log/IdentificationTable.h" static const std::wstring kMockEtwSessionName = L"MockETWSession"; @@ -380,6 +381,7 @@ void MockPresentMonSession::ProcessEvents( } void MockPresentMonSession::Consume(TRACEHANDLE traceHandle) { + util::log::IdentificationTable::AddThisThread("etw-consume"); SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_TIME_CRITICAL); // You must call OpenTrace() prior to calling this function @@ -405,6 +407,7 @@ void MockPresentMonSession::Consume(TRACEHANDLE traceHandle) { } void MockPresentMonSession::Output() { + util::log::IdentificationTable::AddThisThread("frame-out"); // Structures to track processes and statistics from recorded events. std::vector processEvents; std::vector> presentEvents; diff --git a/IntelPresentMon/PresentMonService/PMMainThread.cpp b/IntelPresentMon/PresentMonService/PMMainThread.cpp index b9eb5f55..0f09ff59 100644 --- a/IntelPresentMon/PresentMonService/PMMainThread.cpp +++ b/IntelPresentMon/PresentMonService/PMMainThread.cpp @@ -64,6 +64,8 @@ void EventFlushThreadEntry_(Service* const srv, PresentMon* const pm) return; } + util::log::IdentificationTable::AddThisThread("etw-flush"); + // this is the interval to wait when manual flush is disabled // we still want to run the inner loop to poll in case it gets enabled const uint32_t disabledIntervalMs = 250u; diff --git a/IntelPresentMon/PresentMonService/RealtimePresentMonSession.cpp b/IntelPresentMon/PresentMonService/RealtimePresentMonSession.cpp index 3033e2b2..213d6b37 100644 --- a/IntelPresentMon/PresentMonService/RealtimePresentMonSession.cpp +++ b/IntelPresentMon/PresentMonService/RealtimePresentMonSession.cpp @@ -8,6 +8,7 @@ #include "../CommonUtilities/win/Utilities.h" #include "../CommonUtilities/Qpc.h" #include "../CommonUtilities/Exception.h" +#include "../CommonUtilities/log/IdentificationTable.h" using namespace pmon; using namespace std::literals; @@ -493,6 +494,7 @@ void RealtimePresentMonSession::ProcessEvents( } void RealtimePresentMonSession::Consume(TRACEHANDLE traceHandle) { + util::log::IdentificationTable::AddThisThread("etw-consume"); SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_TIME_CRITICAL); // You must call OpenTrace() prior to calling this function @@ -516,6 +518,7 @@ void RealtimePresentMonSession::Consume(TRACEHANDLE traceHandle) { } void RealtimePresentMonSession::Output() { + util::log::IdentificationTable::AddThisThread("frame-out"); try { // Structures to track processes and statistics from recorded events. std::vector processEvents; From 58099143fff3192117b81f4442fe053e970837fb Mon Sep 17 00:00:00 2001 From: "Taylor, Raymond" Date: Fri, 5 Jun 2026 04:34:49 -0700 Subject: [PATCH 5/5] improving interval waiter cadence & telemetry poll setting --- .../CommonUtilities/IntervalWaiter.cpp | 28 +- .../CommonUtilities/IntervalWaiter.h | 3 + .../PresentMonAPI2/PresentMonAPI.cpp | 2 +- .../PresentMonAPI2/PresentMonAPI.h | 1 + .../PresentMonMiddleware/Middleware.cpp | 4 +- .../PresentMonMiddleware/Middleware.h | 2 +- .../acts/SetTelemetryPeriod.h | 22 +- IntelPresentMon/UnitTests/Timing.cpp | 391 +++++++++++++++++- 8 files changed, 432 insertions(+), 21 deletions(-) diff --git a/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp b/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp index 73e4fef3..1040f07f 100644 --- a/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp +++ b/IntelPresentMon/CommonUtilities/IntervalWaiter.cpp @@ -59,19 +59,41 @@ namespace pmon::util IntervalWaiter::WaitResult IntervalWaiter::Wait() { WaitResult res{}; + // Decide how long to block (if at all) and update the cadence anchor (lastTargetTime_). + // lastTargetTime_ is the scheduled instant of the last completed tick; the next tick is + // always lastTargetTime_ + intervalSeconds_. res.targetSec is that next tick and is always + // the on-time deadline for this call, even when we arrive late. const auto waitTimeSeconds = [=, this, &res] { const auto t = timer_.Peek(); res.targetSec = lastTargetTime_ + intervalSeconds_; - // if we are on-time + if (t <= res.targetSec) { + // On time: wait until the scheduled tick, then advance the anchor to that tick. lastTargetTime_ = res.targetSec; return res.targetSec - t; } - // if we are late, reset target to NOW and do not wait - lastTargetTime_ = t; + + // Late for res.targetSec. Do not wait; report how far past the deadline we are. + // errorSec < 0 means lateness (targetSec - t). Consumers can map targetSec to a + // timestamp via TargetTimeToTimestamp() for poll/window alignment on that grid slot. res.errorSec = res.targetSec - t; + + const auto nextTargetSec = res.targetSec + intervalSeconds_; + if (t <= nextTargetSec) { + // Moderately late: we missed this tick but can still hit the following one on the + // same phase grid. Anchor stays on the missed tick so the next Wait() targets + // nextTargetSec (shorter sleep catches up). + lastTargetTime_ = res.targetSec; + } + else { + // Too late for the next tick as well; abandon the old grid and re-anchor from now + // so the next Wait() schedules intervalSeconds_ from t instead of chasing missed slots. + lastTargetTime_ = t; + } return 0.; }(); + + // On-time path only: sleep/spin until the deadline. errorSec is wait overrun (>= 0), not lateness. if (waitTimeSeconds > 0.) { res.errorSec = WaitFor(waitTimeSeconds); } diff --git a/IntelPresentMon/CommonUtilities/IntervalWaiter.h b/IntelPresentMon/CommonUtilities/IntervalWaiter.h index 462c03d7..745d5ce9 100644 --- a/IntelPresentMon/CommonUtilities/IntervalWaiter.h +++ b/IntelPresentMon/CommonUtilities/IntervalWaiter.h @@ -19,7 +19,9 @@ namespace pmon::util // types struct WaitResult { + // Scheduled tick for this Wait() in timer seconds (on-time grid instant). double targetSec; + // On-time: non-negative wait overrun from WaitFor. Late: negative lateness (targetSec - now). double errorSec; }; struct Options @@ -46,6 +48,7 @@ namespace pmon::util private: double WaitFor(double seconds); double intervalSeconds_; + // Cadence anchor: scheduled time of the last completed (or re-synced) tick. double lastTargetTime_ = 0.; Options options_; PrecisionWaiter waiter_; diff --git a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.cpp b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.cpp index a2fb9446..57a04293 100644 --- a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.cpp +++ b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.cpp @@ -287,7 +287,7 @@ PRESENTMON_API2_EXPORT PM_STATUS pmSetTelemetryPollingPeriod(PM_SESSION_HANDLE h { try { pmlog_dbg("pmSetTelemetryPollingPeriod").pmwatch(handle).pmwatch(deviceId).pmwatch(timeMs); - LookupMiddleware_(handle).SetTelemetryPollingPeriod(deviceId, timeMs); + LookupMiddleware_(handle).SetTelemetryPollingPeriod(deviceId, timeMs ? std::optional{ timeMs } : std::nullopt); return PM_STATUS_SUCCESS; } pmcatch_report_diag(true); diff --git a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h index a14566db..74819ee6 100644 --- a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h +++ b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.h @@ -422,6 +422,7 @@ extern "C" { // free the introspection tree structure PRESENTMON_API2_EXPORT PM_STATUS pmFreeIntrospectionRoot(const PM_INTROSPECTION_ROOT* pRoot); // sets the rate at which hardware telemetry (including CPU) is polled + // a value of zero indicates to use current service setting (default or value requested by other client) PRESENTMON_API2_EXPORT PM_STATUS pmSetTelemetryPollingPeriod(PM_SESSION_HANDLE handle, uint32_t reserved, uint32_t timeMs); #define PM_TELEMETRY_PERIOD_MIN 50 #define PM_TELEMETRY_PERIOD_MAX 5000 diff --git a/IntelPresentMon/PresentMonMiddleware/Middleware.cpp b/IntelPresentMon/PresentMonMiddleware/Middleware.cpp index 5601f3f3..f6e1598c 100644 --- a/IntelPresentMon/PresentMonMiddleware/Middleware.cpp +++ b/IntelPresentMon/PresentMonMiddleware/Middleware.cpp @@ -214,10 +214,10 @@ namespace pmon::mid return *pIntroRoot_; } - void Middleware::SetTelemetryPollingPeriod(uint32_t deviceId, uint32_t timeMs) + void Middleware::SetTelemetryPollingPeriod(uint32_t deviceId, std::optional periodMs) { // note: deviceId is being ignored for the time being, but might be used in the future - pActionClient_->DispatchSync(SetTelemetryPeriod::Params{ timeMs }); + pActionClient_->DispatchSync(SetTelemetryPeriod::Params{ .telemetrySamplePeriodMs = periodMs }); } void Middleware::SetEtwFlushPeriod(std::optional periodMs) diff --git a/IntelPresentMon/PresentMonMiddleware/Middleware.h b/IntelPresentMon/PresentMonMiddleware/Middleware.h index e9ea1add..532c7aab 100644 --- a/IntelPresentMon/PresentMonMiddleware/Middleware.h +++ b/IntelPresentMon/PresentMonMiddleware/Middleware.h @@ -34,7 +34,7 @@ namespace pmon::mid void StartTracking(uint32_t processId); void StartPlaybackTracking(uint32_t processId, bool isBackpressured); void StopTracking(uint32_t processId); - void SetTelemetryPollingPeriod(uint32_t deviceId, uint32_t timeMs); + void SetTelemetryPollingPeriod(uint32_t deviceId, std::optional periodMs); void SetEtwFlushPeriod(std::optional periodMs); void FlushFrames(uint32_t processId); PM_DYNAMIC_QUERY* RegisterDynamicQuery(std::span queryElements, double windowSizeMs, double metricOffsetMs); diff --git a/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h b/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h index 75c6b2d4..e0dcae5b 100644 --- a/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h +++ b/IntelPresentMon/PresentMonService/acts/SetTelemetryPeriod.h @@ -21,7 +21,7 @@ namespace pmon::svc::acts static constexpr const char* Identifier = STRINGIFY(ACT_NAME); struct Params { - uint32_t telemetrySamplePeriodMs; + std::optional telemetrySamplePeriodMs; template void serialize(A& ar) { ar(telemetrySamplePeriodMs); @@ -33,23 +33,25 @@ namespace pmon::svc::acts static Response Execute_(const ACT_EXEC_CTX& ctx, SessionContext& stx, Params&& in) { auto telemetrySamplePeriodMs = in.telemetrySamplePeriodMs; - if (telemetrySamplePeriodMs && telemetrySamplePeriodMs < PM_TELEMETRY_PERIOD_MIN) { + if (telemetrySamplePeriodMs && *telemetrySamplePeriodMs < PM_TELEMETRY_PERIOD_MIN) { pmlog_warn("Telemetry period out of range; clamping to minimum") - .pmwatch(telemetrySamplePeriodMs).pmwatch(PM_TELEMETRY_PERIOD_MIN).diag(); + .pmwatch(*telemetrySamplePeriodMs).pmwatch(PM_TELEMETRY_PERIOD_MIN).diag(); telemetrySamplePeriodMs = PM_TELEMETRY_PERIOD_MIN; } - else if (telemetrySamplePeriodMs > PM_TELEMETRY_PERIOD_MAX) { + else if (telemetrySamplePeriodMs && *telemetrySamplePeriodMs > PM_TELEMETRY_PERIOD_MAX) { pmlog_warn("Telemetry period out of range; clamping to maximum") - .pmwatch(telemetrySamplePeriodMs).pmwatch(PM_TELEMETRY_PERIOD_MAX).diag(); + .pmwatch(*telemetrySamplePeriodMs).pmwatch(PM_TELEMETRY_PERIOD_MAX).diag(); telemetrySamplePeriodMs = PM_TELEMETRY_PERIOD_MAX; } - // set request for this session stx.requestedTelemetryPeriodMs = telemetrySamplePeriodMs; - // update the service ctx.UpdateTelemetryPeriod(); - - pmlog_dbg(std::format("Requested telemetry sample period of {}ms by client [{}]", - telemetrySamplePeriodMs, stx.remotePid)); + if (telemetrySamplePeriodMs) { + pmlog_dbg(std::format("Requested telemetry sample period of {}ms by client [{}]", + *telemetrySamplePeriodMs, stx.remotePid)); + } + else { + pmlog_dbg(std::format("Releasing manual telemetry period override for client [{}]", stx.remotePid)); + } return {}; } }; diff --git a/IntelPresentMon/UnitTests/Timing.cpp b/IntelPresentMon/UnitTests/Timing.cpp index 501c8f1a..f29b29eb 100644 --- a/IntelPresentMon/UnitTests/Timing.cpp +++ b/IntelPresentMon/UnitTests/Timing.cpp @@ -105,6 +105,55 @@ namespace UtilityTests double expectedWaiterErrorSeconds = 0.; }; + struct IntervalWaiterPhaseStepData + { + int step = 0; + double workSeconds = 0.; + double auxiliaryWorkSeconds = 0.; + double waitSeconds = 0.; + double iterationSeconds = 0.; + double expectedIterationSeconds = 0.; + double targetSeconds = 0.; + double expectedTargetSeconds = 0.; + double waiterErrorSeconds = 0.; + double expectedWaiterErrorSeconds = 0.; + double targetAdvanceSeconds = 0.; + }; + + void LogIntervalWaiterPhaseSteps(std::wstring_view testName, const std::vector& steps) + { + for (const auto& result : steps) { + if (result.iterationSeconds > 0. || result.expectedIterationSeconds > 0.) { + Logger::WriteMessage(std::format( + L"{} step {}: work={:.6f}ms auxWork={:.6f}ms wait={:.6f}ms total={:.6f}ms expectedTotal={:.6f}ms target={:.6f}ms expectedTarget={:.6f}ms waiterError={:.6f}ms targetAdvance={:.6f}ms\n", + testName, + result.step, + SecondsToMilliseconds(result.workSeconds), + SecondsToMilliseconds(result.auxiliaryWorkSeconds), + SecondsToMilliseconds(result.waitSeconds), + SecondsToMilliseconds(result.iterationSeconds), + SecondsToMilliseconds(result.expectedIterationSeconds), + SecondsToMilliseconds(result.targetSeconds), + SecondsToMilliseconds(result.expectedTargetSeconds), + SecondsToMilliseconds(result.waiterErrorSeconds), + SecondsToMilliseconds(result.targetAdvanceSeconds)).c_str()); + } + else { + Logger::WriteMessage(std::format( + L"{} step {}: work={:.6f}ms auxWork={:.6f}ms wait={:.6f}ms target={:.6f}ms expectedTarget={:.6f}ms waiterError={:.6f}ms targetAdvance={:.6f}ms\n", + testName, + result.step, + SecondsToMilliseconds(result.workSeconds), + SecondsToMilliseconds(result.auxiliaryWorkSeconds), + SecondsToMilliseconds(result.waitSeconds), + SecondsToMilliseconds(result.targetSeconds), + SecondsToMilliseconds(result.expectedTargetSeconds), + SecondsToMilliseconds(result.waiterErrorSeconds), + SecondsToMilliseconds(result.targetAdvanceSeconds)).c_str()); + } + } + } + struct HighResolutionWaitableTimerIterationData { double waitSeconds = 0.; @@ -320,6 +369,7 @@ namespace UtilityTests constexpr auto singleCadenceErrorThreshold = 0.000'180; constexpr auto aggregateCadenceErrorThresholdPerIteration = 0.000'070; constexpr auto reportedLateErrorThreshold = immediateReturnThreshold; + constexpr auto lateOverrunSeconds = lateWorkSeconds - waitInterval; std::vector results; results.reserve(iterations); @@ -339,8 +389,11 @@ namespace UtilityTests for (int i = 0; i < iterations; i++) { const auto iteration = i + 1; const auto late = iteration % latePeriod == 0; + const auto recoveryAfterLate = !late && iteration > 1 && ((iteration - 1) % latePeriod == 0); const auto workSeconds = late ? lateWorkSeconds : onTimeWorkSeconds; - const auto expectedIterationSeconds = late ? lateWorkSeconds : waitInterval; + const auto expectedIterationSeconds = late ? lateWorkSeconds + : recoveryAfterLate ? waitInterval - lateOverrunSeconds + : waitInterval; iterationTimer.Mark(); workTimer.Mark(); workTimer.SpinWaitUntil(workSeconds); @@ -368,7 +421,8 @@ namespace UtilityTests }); if (!late) { - const auto cadenceError = iterationSeconds - waitInterval; + const auto expectedCadenceSeconds = recoveryAfterLate ? waitInterval - lateOverrunSeconds : waitInterval; + const auto cadenceError = iterationSeconds - expectedCadenceSeconds; totalOnTimeCadenceSeconds += iterationSeconds; aggregateOnTimeCadenceError += std::abs(cadenceError); onTimeIterations++; @@ -388,7 +442,13 @@ namespace UtilityTests SecondsToMilliseconds(result.waiterErrorSeconds), result.late).c_str()); } - const auto expectedOnTimeCadenceSeconds = waitInterval * onTimeIterations; + double expectedOnTimeCadenceSeconds = 0.; + for (const auto& result : results) { + if (!result.late) { + const auto recoveryAfterLate = result.iteration > 1 && ((result.iteration - 1) % latePeriod == 0); + expectedOnTimeCadenceSeconds += recoveryAfterLate ? waitInterval - lateOverrunSeconds : waitInterval; + } + } const auto averageIterationError = aggregateIterationError / iterations; const auto averageOnTimeCadenceError = aggregateOnTimeCadenceError / onTimeIterations; Logger::WriteMessage(std::format( @@ -410,7 +470,9 @@ namespace UtilityTests AssertErrorWithinTolerance(L"IntervalWaiterLateChrono late reported error", result.iteration, result.waiterErrorSeconds, result.expectedWaiterErrorSeconds, result.waiterErrorSeconds - result.expectedWaiterErrorSeconds, reportedLateErrorThreshold); } else { - AssertErrorWithinTolerance(L"IntervalWaiterLateChrono on-time cadence", result.iteration, result.iterationSeconds, waitInterval, result.iterationErrorSeconds, singleCadenceErrorThreshold); + const auto recoveryAfterLate = result.iteration > 1 && ((result.iteration - 1) % latePeriod == 0); + const auto expectedCadenceSeconds = recoveryAfterLate ? waitInterval - lateOverrunSeconds : waitInterval; + AssertErrorWithinTolerance(L"IntervalWaiterLateChrono on-time cadence", result.iteration, result.iterationSeconds, expectedCadenceSeconds, result.iterationSeconds - expectedCadenceSeconds, singleCadenceErrorThreshold); } } AssertAggregateErrorWithinTolerance( @@ -427,5 +489,326 @@ namespace UtilityTests averageOnTimeCadenceError, aggregateCadenceErrorThresholdPerIteration); } + TEST_METHOD(IntervalWaiterPhaseRecoveryPreservesGrid) + { + constexpr auto waitInterval = 0.010; + constexpr auto onTimeWorkSeconds = 0.004; + constexpr auto moderateLateWorkSeconds = 0.012; + constexpr auto lateOverrunSeconds = moderateLateWorkSeconds - waitInterval; + constexpr auto immediateReturnThreshold = 0.000'060; + constexpr auto targetThreshold = 0.000'001; + constexpr auto cadenceThreshold = 0.000'180; + constexpr std::wstring_view testName = L"IntervalWaiterPhaseRecoveryPreservesGrid"; + + std::vector results; + results.reserve(4); + + util::IntervalWaiter waiter{ waitInterval, util::IntervalWaiter::Options{ + .mechanism = util::WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = util::PrecisionWaiter::standardWaitBuffer, + } }; + util::QpcTimer workTimer; + util::QpcTimer waitTimer; + util::QpcTimer iterationTimer; + + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto primeWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto prime = waiter.Wait(); + results.push_back({ + .step = 1, + .workSeconds = primeWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .targetSeconds = prime.targetSec, + .expectedTargetSeconds = waitInterval, + .waiterErrorSeconds = prime.errorSec, + }); + + workTimer.Mark(); + workTimer.SpinWaitUntil(moderateLateWorkSeconds); + const auto lateWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto late = waiter.Wait(); + results.push_back({ + .step = 2, + .workSeconds = lateWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .targetSeconds = late.targetSec, + .expectedTargetSeconds = 2. * waitInterval, + .waiterErrorSeconds = late.errorSec, + }); + const auto expectedRecoveryIterationSeconds = waitInterval + late.errorSec; + + iterationTimer.Mark(); + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto recoveryWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto recovery = waiter.Wait(); + results.push_back({ + .step = 3, + .workSeconds = recoveryWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .iterationSeconds = iterationTimer.Peek(), + .expectedIterationSeconds = expectedRecoveryIterationSeconds, + .targetSeconds = recovery.targetSec, + .expectedTargetSeconds = 3. * waitInterval, + .waiterErrorSeconds = recovery.errorSec, + }); + + iterationTimer.Mark(); + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto resumedWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto resumed = waiter.Wait(); + results.push_back({ + .step = 4, + .workSeconds = resumedWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .iterationSeconds = iterationTimer.Peek(), + .expectedIterationSeconds = waitInterval, + .targetSeconds = resumed.targetSec, + .expectedTargetSeconds = 4. * waitInterval, + .waiterErrorSeconds = resumed.errorSec, + }); + + LogIntervalWaiterPhaseSteps(testName, results); + + AssertErrorWithinTolerance(testName, 1, results[0].targetSeconds, results[0].expectedTargetSeconds, results[0].targetSeconds - results[0].expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance(testName, 2, results[1].targetSeconds, results[1].expectedTargetSeconds, results[1].targetSeconds - results[1].expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance(L"IntervalWaiterPhaseRecoveryPreservesGrid late immediate wait", 2, results[1].waitSeconds, 0., results[1].waitSeconds, immediateReturnThreshold); + Assert::IsTrue(results[1].waiterErrorSeconds < 0.); + Assert::IsTrue(results[1].waiterErrorSeconds > -(waitInterval + lateOverrunSeconds)); + AssertErrorWithinTolerance(testName, 3, results[2].targetSeconds, results[2].expectedTargetSeconds, results[2].targetSeconds - results[2].expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance( + L"IntervalWaiterPhaseRecoveryPreservesGrid recovery cadence", + 3, + results[2].iterationSeconds, + results[2].expectedIterationSeconds, + results[2].iterationSeconds - results[2].expectedIterationSeconds, + cadenceThreshold); + AssertErrorWithinTolerance(testName, 4, results[3].targetSeconds, results[3].expectedTargetSeconds, results[3].targetSeconds - results[3].expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance( + L"IntervalWaiterPhaseRecoveryPreservesGrid resumed cadence", + 4, + results[3].iterationSeconds, + results[3].expectedIterationSeconds, + results[3].iterationSeconds - results[3].expectedIterationSeconds, + cadenceThreshold); + } + TEST_METHOD(IntervalWaiterPhaseRecoveryConsecutiveModerateLate) + { + constexpr auto waitInterval = 0.010; + constexpr auto onTimeWorkSeconds = 0.004; + constexpr auto moderateLateWorkSeconds = 0.012; + constexpr auto immediateReturnThreshold = 0.000'060; + constexpr auto targetThreshold = 0.000'001; + constexpr std::wstring_view testName = L"IntervalWaiterPhaseRecoveryConsecutiveModerateLate"; + + std::vector results; + results.reserve(3); + + util::IntervalWaiter waiter{ waitInterval, util::IntervalWaiter::Options{ + .mechanism = util::WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = util::PrecisionWaiter::standardWaitBuffer, + } }; + util::QpcTimer workTimer; + util::QpcTimer waitTimer; + + for (int step = 1; step <= 2; step++) { + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto onTimeWorkSecondsActual = workTimer.Peek(); + waiter.Wait(); + workTimer.Mark(); + workTimer.SpinWaitUntil(moderateLateWorkSeconds); + const auto moderateLateWorkSecondsActual = workTimer.Peek(); + waitTimer.Mark(); + const auto late = waiter.Wait(); + results.push_back({ + .step = step, + .workSeconds = moderateLateWorkSecondsActual, + .auxiliaryWorkSeconds = onTimeWorkSecondsActual, + .waitSeconds = waitTimer.Peek(), + .targetSeconds = late.targetSec, + .expectedTargetSeconds = double(step) * 2. * waitInterval, + .waiterErrorSeconds = late.errorSec, + }); + } + + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto nextWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto next = waiter.Wait(); + results.push_back({ + .step = 3, + .workSeconds = nextWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .targetSeconds = next.targetSec, + .expectedTargetSeconds = 5. * waitInterval, + .waiterErrorSeconds = next.errorSec, + }); + + LogIntervalWaiterPhaseSteps(testName, results); + + for (int step = 1; step <= 2; step++) { + const auto& result = results[step - 1]; + AssertErrorWithinTolerance(testName, step, result.targetSeconds, result.expectedTargetSeconds, result.targetSeconds - result.expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance(L"IntervalWaiterPhaseRecoveryConsecutiveModerateLate late immediate wait", step, result.waitSeconds, 0., result.waitSeconds, immediateReturnThreshold); + } + const auto& nextResult = results[2]; + AssertErrorWithinTolerance(testName, 3, nextResult.targetSeconds, nextResult.expectedTargetSeconds, nextResult.targetSeconds - nextResult.expectedTargetSeconds, targetThreshold); + } + TEST_METHOD(IntervalWaiterPhaseResetMissesNextBus) + { + constexpr auto waitInterval = 0.010; + constexpr auto onTimeWorkSeconds = 0.004; + constexpr auto phaseResetWorkSeconds = 0.022; + constexpr auto immediateReturnThreshold = 0.000'060; + constexpr auto reportedLateErrorThreshold = 0.000'180; + constexpr auto targetThreshold = 0.000'001; + constexpr auto cadenceThreshold = 0.000'180; + constexpr auto phaseAdvanceThreshold = 0.000'180; + constexpr std::wstring_view testName = L"IntervalWaiterPhaseResetMissesNextBus"; + + std::vector results; + results.reserve(3); + + util::IntervalWaiter waiter{ waitInterval, util::IntervalWaiter::Options{ + .mechanism = util::WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = util::PrecisionWaiter::standardWaitBuffer, + } }; + util::QpcTimer workTimer; + util::QpcTimer waitTimer; + util::QpcTimer iterationTimer; + + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto primeWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto prime = waiter.Wait(); + results.push_back({ + .step = 1, + .workSeconds = primeWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .targetSeconds = prime.targetSec, + .expectedTargetSeconds = waitInterval, + .waiterErrorSeconds = prime.errorSec, + }); + + workTimer.Mark(); + workTimer.SpinWaitUntil(phaseResetWorkSeconds); + const auto actualResetWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto missedBuses = waiter.Wait(); + results.push_back({ + .step = 2, + .workSeconds = actualResetWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .targetSeconds = missedBuses.targetSec, + .expectedTargetSeconds = 2. * waitInterval, + .waiterErrorSeconds = missedBuses.errorSec, + .expectedWaiterErrorSeconds = waitInterval - actualResetWorkSeconds, + }); + + iterationTimer.Mark(); + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto afterResetWorkSeconds = workTimer.Peek(); + waitTimer.Mark(); + const auto afterReset = waiter.Wait(); + results.push_back({ + .step = 3, + .workSeconds = afterResetWorkSeconds, + .waitSeconds = waitTimer.Peek(), + .iterationSeconds = iterationTimer.Peek(), + .expectedIterationSeconds = waitInterval, + .targetSeconds = afterReset.targetSec, + .waiterErrorSeconds = afterReset.errorSec, + .targetAdvanceSeconds = afterReset.targetSec - missedBuses.targetSec, + }); + + LogIntervalWaiterPhaseSteps(testName, results); + + AssertErrorWithinTolerance(testName, 1, results[0].targetSeconds, results[0].expectedTargetSeconds, results[0].targetSeconds - results[0].expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance(testName, 2, results[1].targetSeconds, results[1].expectedTargetSeconds, results[1].targetSeconds - results[1].expectedTargetSeconds, targetThreshold); + AssertErrorWithinTolerance(L"IntervalWaiterPhaseResetMissesNextBus late immediate wait", 2, results[1].waitSeconds, 0., results[1].waitSeconds, immediateReturnThreshold); + Assert::IsTrue(results[1].waiterErrorSeconds < -waitInterval); + AssertErrorWithinTolerance( + L"IntervalWaiterPhaseResetMissesNextBus late reported error", + 2, + results[1].waiterErrorSeconds, + results[1].expectedWaiterErrorSeconds, + results[1].waiterErrorSeconds - results[1].expectedWaiterErrorSeconds, + reportedLateErrorThreshold); + Assert::IsTrue(results[2].targetAdvanceSeconds > waitInterval + phaseAdvanceThreshold); + AssertErrorWithinTolerance( + L"IntervalWaiterPhaseResetMissesNextBus post-reset cadence", + 3, + results[2].iterationSeconds, + results[2].expectedIterationSeconds, + results[2].iterationSeconds - results[2].expectedIterationSeconds, + cadenceThreshold); + } + TEST_METHOD(IntervalWaiterPhaseResetVersusRecoveryTargetAdvance) + { + constexpr auto waitInterval = 0.010; + constexpr auto onTimeWorkSeconds = 0.004; + constexpr auto moderateLateWorkSeconds = 0.012; + constexpr auto phaseResetWorkSeconds = 0.022; + constexpr auto phaseAdvanceThreshold = 0.000'180; + constexpr std::wstring_view testName = L"IntervalWaiterPhaseResetVersusRecoveryTargetAdvance"; + + auto measureTargetAdvance = [&](double lateWorkSeconds, int step) { + util::IntervalWaiter waiter{ waitInterval, util::IntervalWaiter::Options{ + .mechanism = util::WaitMechanism::HighPrecisionTimer, + .spinBufferSeconds = util::PrecisionWaiter::standardWaitBuffer, + } }; + util::QpcTimer workTimer; + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + waiter.Wait(); + workTimer.Mark(); + workTimer.SpinWaitUntil(lateWorkSeconds); + const auto actualLateWorkSeconds = workTimer.Peek(); + const auto late = waiter.Wait(); + workTimer.Mark(); + workTimer.SpinWaitUntil(onTimeWorkSeconds); + const auto next = waiter.Wait(); + return IntervalWaiterPhaseStepData{ + .step = step, + .workSeconds = actualLateWorkSeconds, + .targetSeconds = late.targetSec, + .expectedTargetSeconds = next.targetSec, + .waiterErrorSeconds = late.errorSec, + .targetAdvanceSeconds = next.targetSec - late.targetSec, + }; + }; + + std::vector results; + results.push_back(measureTargetAdvance(moderateLateWorkSeconds, 1)); + results.push_back(measureTargetAdvance(phaseResetWorkSeconds, 2)); + + LogIntervalWaiterPhaseSteps(testName, results); + Logger::WriteMessage(std::format( + L"{} summary: recoveryAdvance={:.6f}ms resetAdvance={:.6f}ms interval={:.6f}ms\n", + testName, + SecondsToMilliseconds(results[0].targetAdvanceSeconds), + SecondsToMilliseconds(results[1].targetAdvanceSeconds), + SecondsToMilliseconds(waitInterval)).c_str()); + + AssertErrorWithinTolerance( + L"IntervalWaiterPhaseResetVersusRecoveryTargetAdvance recovery advance", + 1, + results[0].targetAdvanceSeconds, + waitInterval, + results[0].targetAdvanceSeconds - waitInterval, + phaseAdvanceThreshold); + Assert::IsTrue(results[1].targetAdvanceSeconds > waitInterval + phaseAdvanceThreshold); + Assert::IsTrue(results[1].targetAdvanceSeconds > results[0].targetAdvanceSeconds + phaseAdvanceThreshold); + } }; }