diff --git a/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.cpp b/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.cpp index 269bb3cc..e1ee8e3c 100644 --- a/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.cpp +++ b/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.cpp @@ -119,6 +119,7 @@ namespace pmon::util::metrics auto metrics = ComputeFrameMetrics( qpc, present, + chainState.lastDisplayedScreenTime, screenTime, nextScreenTime, isDisplayed, @@ -162,6 +163,7 @@ namespace pmon::util::metrics auto metrics = ComputeFrameMetrics( qpc, present, + chainState.lastDisplayedScreenTime, screenTime, nextScreenTime, isDisplayedInstance, @@ -183,6 +185,10 @@ namespace pmon::util::metrics const bool shouldUpdateSwapChain = (nextDisplayed != nullptr); for (size_t displayIndex = indexing.startIndex; displayIndex < indexing.endIndex; ++displayIndex) { + const uint64_t previousDisplayedScreenTime = + displayIndex > 0 + ? present.displayed[displayIndex - 1].second + : chainState.lastDisplayedScreenTime; uint64_t screenTime = present.displayed[displayIndex].second; uint64_t nextScreenTime = 0; @@ -207,6 +213,7 @@ namespace pmon::util::metrics auto metrics = ComputeFrameMetrics( qpc, present, + previousDisplayedScreenTime, screenTime, nextScreenTime, isDisplayedInstance, @@ -235,6 +242,7 @@ namespace pmon::util::metrics ComputedMetrics ComputeFrameMetrics( const QpcConverter& qpc, const FrameData& present, + uint64_t previousDisplayedScreenTime, uint64_t screenTime, uint64_t nextScreenTime, bool isDisplayed, @@ -258,6 +266,7 @@ namespace pmon::util::metrics qpc, present, chain, + previousDisplayedScreenTime, isDisplayed, screenTime, nextScreenTime, diff --git a/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.h b/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.h index 720f4ac1..d9d9fe4b 100644 --- a/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.h +++ b/IntelPresentMon/CommonUtilities/mc/MetricsCalculator.h @@ -50,6 +50,7 @@ namespace pmon::util::metrics ComputedMetrics ComputeFrameMetrics( const QpcConverter& qpc, const FrameData& present, + uint64_t previousDisplayedScreenTime, uint64_t screenTime, uint64_t nextScreenTime, bool isDisplayed, diff --git a/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorDisplay.cpp b/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorDisplay.cpp index c812e7ee..0afd813f 100644 --- a/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorDisplay.cpp +++ b/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorDisplay.cpp @@ -26,12 +26,12 @@ namespace pmon::util::metrics // Helper dedicated to computing msBetweenDisplayChange, matching legacy ReportMetricsHelper behavior. double ComputeMsBetweenDisplayChange( const QpcConverter& qpc, - const SwapChainCoreState& chain, + uint64_t previousDisplayedScreenTime, bool isDisplayed, uint64_t screenTime) { return isDisplayed - ? qpc.DeltaUnsignedMilliSeconds(chain.lastDisplayedScreenTime, screenTime) + ? qpc.DeltaUnsignedMilliSeconds(previousDisplayedScreenTime, screenTime) : 0.0; } @@ -88,6 +88,24 @@ namespace pmon::util::metrics } + bool IsGeneratedFrame(FrameType frameType) + { + return frameType == FrameType::Repeated || + frameType == FrameType::Intel_XEFG || + frameType == FrameType::AMD_AFMF; + } + + + bool PresentHasGeneratedDisplayEntry(const FrameData& present) + { + const auto n = present.displayed.Size(); + for (size_t i = 0; i < n; ++i) { + if (IsGeneratedFrame(present.displayed[i].first)) { + return true; + } + } + return false; + } } // ---- NV collapsed/runt correction ---- @@ -145,16 +163,32 @@ namespace pmon::util::metrics // hasNextDisplayed result.hasNextDisplayed = (nextDisplayed != nullptr); - // Figure out range to process based on three cases: - // Case 1: Not displayed → empty range [0, 0) - // Case 2: Displayed, no next → process [0..N-2], postpone N-1 → range [0, N-1) - // Case 3: Displayed, with next → process postponed [N-1] → range [N-1, N) + // Figure out range to process: + // Case 1: Not displayed -> empty range [0, 0) + // Any generated frame: Repeated / Intel_XEFG / AMD_AFMF needs next app sim + // for animation metrics -> defer entire present until next App Displayed exists. + // No next: [0, 0). With next: [0, displayCount). + // Otherwise (legacy): + // Case 2: Displayed, no next -> [0, displayCount - 1) (postpone last) + // Case 3: Displayed, with next -> [displayCount - 1, displayCount) (process last only) + + const bool needsNextPresentForGeneratedFrameMetrics = + displayed && displayCount > 0 && + PresentHasGeneratedDisplayEntry(present); if (!displayed || displayCount == 0) { // Case 1: Not displayed result.startIndex = 0; result.endIndex = 0; // Empty range } + else if (needsNextPresentForGeneratedFrameMetrics && nextDisplayed == nullptr) { + result.startIndex = 0; + result.endIndex = 0; + } + else if (needsNextPresentForGeneratedFrameMetrics && nextDisplayed != nullptr) { + result.startIndex = 0; + result.endIndex = displayCount; + } else if (nextDisplayed == nullptr) { // Case 2: Postpone last display result.startIndex = 0; @@ -166,8 +200,7 @@ namespace pmon::util::metrics result.endIndex = displayCount; // One past [N-1] = [N] } - // appIndex - find first NotSet or Application frame - // Search from startIndex through ALL displays (not just the processing range) + // appIndex - find first NotSet or Application frame (search from startIndex; legacy) result.appIndex = std::numeric_limits::max(); if (displayCount > 0) { for (size_t i = result.startIndex; i < displayCount; ++i) { @@ -189,13 +222,14 @@ namespace pmon::util::metrics const QpcConverter& qpc, const FrameData& present, const SwapChainCoreState& swapChain, + uint64_t previousDisplayedScreenTime, bool isDisplayed, uint64_t screenTime, uint64_t nextScreenTime, FrameMetrics& metrics) { metrics.msUntilDisplayed = ComputeMsUntilDisplayed(qpc, present, isDisplayed, screenTime); - metrics.msBetweenDisplayChange = ComputeMsBetweenDisplayChange(qpc, swapChain, isDisplayed, screenTime); + metrics.msBetweenDisplayChange = ComputeMsBetweenDisplayChange(qpc, previousDisplayedScreenTime, isDisplayed, screenTime); metrics.msDisplayedTime = ComputeMsDisplayedTime(qpc, isDisplayed, screenTime, nextScreenTime); metrics.msFlipDelay = ComputeMsFlipDelay(qpc, present, isDisplayed); metrics.msDisplayLatency = ComputeMsDisplayLatency(qpc, swapChain, present, isDisplayed, screenTime); diff --git a/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorInternal.h b/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorInternal.h index 2829b1a5..5d72fa9c 100644 --- a/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorInternal.h +++ b/IntelPresentMon/CommonUtilities/mc/MetricsCalculatorInternal.h @@ -17,6 +17,7 @@ namespace pmon::util::metrics const QpcConverter& qpc, const FrameData& present, const SwapChainCoreState& swapChain, + uint64_t previousDisplayedScreenTime, bool isDisplayed, uint64_t screenTime, uint64_t nextScreenTime, diff --git a/IntelPresentMon/UnitTests/MetricsCore.cpp b/IntelPresentMon/UnitTests/MetricsCore.cpp index 895f4c66..36d50892 100644 --- a/IntelPresentMon/UnitTests/MetricsCore.cpp +++ b/IntelPresentMon/UnitTests/MetricsCore.cpp @@ -1506,6 +1506,353 @@ TEST_CLASS(ComputeMetricsForPresentTests) Assert::AreEqual(uint64_t(42'200), chain.lastDisplayedScreenTime); Assert::AreEqual(uint64_t(999), chain.lastDisplayedFlipDelay); } + + TEST_METHOD(ComputeMetricsForPresent_IntelXefg_MultiPresentSequence_VaryingDisplayedVectorSizes) + { + QpcConverter qpc(10'000'000, 0); + SwapChainCoreState chain{}; + chain.lastDisplayedScreenTime = 5; + + auto assertRow = [&](const auto& result, FrameType expectedFrameType, uint64_t expectedScreenTime, uint64_t expectedBetweenStart, uint64_t expectedDisplayedEnd, uint64_t expectedPresentStart, uint64_t expectedCpuStart, uint64_t expectedReadyTime) + { + const auto& metrics = result.metrics; + Assert::IsTrue(metrics.frameType == expectedFrameType); + Assert::AreEqual(expectedScreenTime, metrics.screenTimeQpc); + + double expectedBetween = qpc.DeltaUnsignedMilliSeconds(expectedBetweenStart, expectedScreenTime); + Assert::AreEqual(expectedBetween, metrics.msBetweenDisplayChange, 0.0001); + + double expectedDisplayedTime = qpc.DeltaUnsignedMilliSeconds(expectedScreenTime, expectedDisplayedEnd); + Assert::AreEqual(expectedDisplayedTime, metrics.msDisplayedTime, 0.0001); + + double expectedUntilDisplayed = qpc.DeltaUnsignedMilliSeconds(expectedPresentStart, expectedScreenTime); + Assert::AreEqual(expectedUntilDisplayed, metrics.msUntilDisplayed, 0.0001); + + double expectedDisplayLatency = qpc.DeltaUnsignedMilliSeconds(expectedCpuStart, expectedScreenTime); + Assert::AreEqual(expectedDisplayLatency, metrics.msDisplayLatency, 0.0001); + + double expectedReadyTimeToDisplayLatency = qpc.DeltaUnsignedMilliSeconds(expectedReadyTime, expectedScreenTime); + Assert::AreEqual(expectedReadyTimeToDisplayLatency, metrics.msReadyTimeToDisplayLatency, 0.0001); + + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msFlipDelay), + L"msFlipDelay should be stored as missing (NaN)"); + }; + + FrameData frameA = MakeFrame( + PresentResult::Presented, + 1, + 1, + 1, + { + { FrameType::Intel_XEFG, 10 }, + { FrameType::Intel_XEFG, 20 }, + { FrameType::Intel_XEFG, 30 }, + { FrameType::Application, 40 }, + }); + + FrameData frameB = MakeFrame( + PresentResult::Presented, + 45, + 1, + 45, + { + { FrameType::Application, 55 }, + }); + + FrameData frameC = MakeFrame( + PresentResult::Presented, + 60, + 1, + 60, + { + { FrameType::Intel_XEFG, 70 }, + { FrameType::Application, 90 }, + }); + + FrameData frameD = MakeFrame( + PresentResult::Presented, + 95, + 1, + 95, + { + { FrameType::Intel_XEFG, 110 }, + { FrameType::Intel_XEFG, 130 }, + { FrameType::Application, 160 }, + }); + + FrameData frameE = MakeFrame( + PresentResult::Presented, + 170, + 1, + 170, + { + { FrameType::Application, 180 }, + }); + + auto resultsA0 = ComputeMetricsForPresent(qpc, frameA, nullptr, chain); + Assert::AreEqual(size_t(3), resultsA0.size(), L"Frame A should emit only generated rows until a later displayed present finalizes the trailing Application row."); + assertRow(resultsA0[0], FrameType::Intel_XEFG, 10, 5, 20, frameA.presentStartTime, 0, frameA.readyTime); + assertRow(resultsA0[1], FrameType::Intel_XEFG, 20, 10, 30, frameA.presentStartTime, 0, frameA.readyTime); + assertRow(resultsA0[2], FrameType::Intel_XEFG, 30, 20, 40, frameA.presentStartTime, 0, frameA.readyTime); + + auto resultsA1 = ComputeMetricsForPresent(qpc, frameA, &frameB, chain); + Assert::AreEqual(size_t(1), resultsA1.size(), L"Frame A's trailing Application row should emit only when Frame B is processed as the next displayed present."); + assertRow(resultsA1[0], FrameType::Application, 40, 30, 55, frameA.presentStartTime, 0, frameA.readyTime); + + auto resultsB0 = ComputeMetricsForPresent(qpc, frameB, nullptr, chain); + Assert::AreEqual(size_t(0), resultsB0.size(), L"A single Application display should stay postponed until a later displayed present is processed."); + + auto resultsB1 = ComputeMetricsForPresent(qpc, frameB, &frameC, chain); + Assert::AreEqual(size_t(1), resultsB1.size()); + assertRow(resultsB1[0], FrameType::Application, 55, 40, 70, frameB.presentStartTime, frameA.presentStartTime + frameA.timeInPresent, frameB.readyTime); + + auto resultsC0 = ComputeMetricsForPresent(qpc, frameC, nullptr, chain); + Assert::AreEqual(size_t(1), resultsC0.size(), L"Frame C should emit only its generated row before the trailing Application row is finalized."); + assertRow(resultsC0[0], FrameType::Intel_XEFG, 70, 55, 90, frameC.presentStartTime, frameB.presentStartTime + frameB.timeInPresent, frameC.readyTime); + + auto resultsC1 = ComputeMetricsForPresent(qpc, frameC, &frameD, chain); + Assert::AreEqual(size_t(1), resultsC1.size()); + assertRow(resultsC1[0], FrameType::Application, 90, 70, 110, frameC.presentStartTime, frameB.presentStartTime + frameB.timeInPresent, frameC.readyTime); + + auto resultsD0 = ComputeMetricsForPresent(qpc, frameD, nullptr, chain); + Assert::AreEqual(size_t(2), resultsD0.size(), L"Frame D should emit its generated rows and postpone only the trailing Application row."); + assertRow(resultsD0[0], FrameType::Intel_XEFG, 110, 90, 130, frameD.presentStartTime, frameC.presentStartTime + frameC.timeInPresent, frameD.readyTime); + assertRow(resultsD0[1], FrameType::Intel_XEFG, 130, 110, 160, frameD.presentStartTime, frameC.presentStartTime + frameC.timeInPresent, frameD.readyTime); + + auto resultsD1 = ComputeMetricsForPresent(qpc, frameD, &frameE, chain); + Assert::AreEqual(size_t(1), resultsD1.size(), L"Frame D's trailing Application row should emit only when a later displayed present is provided."); + assertRow(resultsD1[0], FrameType::Application, 160, 130, 180, frameD.presentStartTime, frameC.presentStartTime + frameC.timeInPresent, frameD.readyTime); + } + + TEST_METHOD(ComputeMetricsForPresent_IntelXefg_EqualScreenTimeGeneratedFrameSequence) + { + QpcConverter qpc(10'000'000, 0); + SwapChainCoreState chain{}; + chain.lastDisplayedScreenTime = 200; + + FrameData priorApp{}; + priorApp.presentStartTime = 190; + priorApp.timeInPresent = 10; + chain.lastAppPresent = priorApp; + + FrameData frameX = MakeFrame( + PresentResult::Presented, + 205, + 15, + 208, + { + { FrameType::Intel_XEFG, 210 }, + { FrameType::Intel_XEFG, 210 }, + { FrameType::Intel_XEFG, 210 }, + { FrameType::Application, 240 }, + }, + 0, + 0, + 12); + + FrameData frameY = MakeFrame( + PresentResult::Presented, + 260, + 15, + 265, + { + { FrameType::Application, 300 }, + }); + + const uint64_t expectedCpuStart = priorApp.presentStartTime + priorApp.timeInPresent; + + auto assertRow = [&](const auto& result, FrameType expectedFrameType, uint64_t expectedScreenTime, uint64_t expectedBetweenStart, uint64_t expectedDisplayedEnd) + { + const auto& metrics = result.metrics; + + Assert::IsTrue(metrics.frameType == expectedFrameType); + Assert::AreEqual(expectedScreenTime, metrics.screenTimeQpc); + + Assert::AreEqual( + qpc.DeltaUnsignedMilliSeconds(expectedBetweenStart, expectedScreenTime), + metrics.msBetweenDisplayChange, + 0.0001); + + Assert::AreEqual( + qpc.DeltaUnsignedMilliSeconds(expectedScreenTime, expectedDisplayedEnd), + metrics.msDisplayedTime, + 0.0001); + + Assert::AreEqual( + qpc.DeltaUnsignedMilliSeconds(frameX.presentStartTime, expectedScreenTime), + metrics.msUntilDisplayed, + 0.0001); + + Assert::AreEqual( + qpc.DeltaUnsignedMilliSeconds(expectedCpuStart, expectedScreenTime), + metrics.msDisplayLatency, + 0.0001); + + Assert::AreEqual( + qpc.DeltaUnsignedMilliSeconds(frameX.readyTime, expectedScreenTime), + metrics.msReadyTimeToDisplayLatency, + 0.0001); + + Assert::AreEqual( + qpc.DurationMilliSeconds(frameX.flipDelay), + metrics.msFlipDelay, + 0.0001); + }; + + auto resultsX0 = ComputeMetricsForPresent(qpc, frameX, nullptr, chain); + Assert::AreEqual(size_t(3), resultsX0.size(), L"Frame X should emit all three generated rows and postpone the trailing Application row."); + assertRow(resultsX0[0], FrameType::Intel_XEFG, 210, 200, 210); + assertRow(resultsX0[1], FrameType::Intel_XEFG, 210, 210, 210); + assertRow(resultsX0[2], FrameType::Intel_XEFG, 210, 210, 240); + + auto resultsX1 = ComputeMetricsForPresent(qpc, frameX, &frameY, chain); + Assert::AreEqual(size_t(1), resultsX1.size(), L"Frame X's trailing Application row should emit only when Frame Y is processed as the next displayed present."); + assertRow(resultsX1[0], FrameType::Application, 240, 210, 300); + } + + TEST_METHOD(ComputeMetricsForPresent_IntelXefg_GeneratedRowsRemainDisplayOnlyUntilTrailingApplicationFinalizes) + { + QpcConverter qpc(10'000'000, 0); + SwapChainCoreState chain{}; + chain.animationErrorSource = AnimationErrorSource::AppProvider; + chain.lastDisplayedScreenTime = 5; + chain.lastDisplayedAppScreenTime = 5; + chain.lastSimStartTime = 80; + chain.firstAppSimStartTime = 80; + chain.lastDisplayedSimStartTime = 80; + + FrameData priorApp = MakeFrame( + PresentResult::Presented, + 1, + 2, + 3, + { + { FrameType::Application, 5 }, + }); + chain.lastAppPresent = priorApp; + + FrameData frameA = MakeFrame( + PresentResult::Presented, + 6, + 4, + 8, + { + { FrameType::Intel_XEFG, 10 }, + { FrameType::Intel_XEFG, 20 }, + { FrameType::Intel_XEFG, 30 }, + { FrameType::Application, 40 }, + }, + 90, + 95, + 2); + frameA.gpuStartTime = 12; + frameA.gpuDuration = 6; + frameA.inputTime = 4; + frameA.mouseClickTime = 5; + frameA.appInputSample = { 3, InputDeviceType::Mouse }; + frameA.appSleepStartTime = 11; + frameA.appSleepEndTime = 12; + frameA.appRenderSubmitStartTime = 13; + + FrameData frameB = MakeFrame( + PresentResult::Presented, + 50, + 4, + 52, + { + { FrameType::Application, 55 }, + }); + + auto assertGeneratedDisplayOnlyRow = [&](const auto& result, uint64_t expectedScreenTime) + { + const auto& metrics = result.metrics; + + Assert::IsTrue(metrics.frameType == FrameType::Intel_XEFG); + Assert::AreEqual(expectedScreenTime, metrics.screenTimeQpc); + Assert::IsTrue(metrics.msDisplayLatency > 0.0); + Assert::IsTrue(metrics.msDisplayedTime > 0.0); + Assert::IsTrue(metrics.msUntilDisplayed > 0.0); + Assert::IsTrue(metrics.msBetweenDisplayChange > 0.0); + Assert::IsFalse(IsMissingFrameMetricValue(metrics.msReadyTimeToDisplayLatency), + L"msReadyTimeToDisplayLatency should not be stored as missing (NaN)"); + Assert::IsFalse(IsMissingFrameMetricValue(metrics.msFlipDelay), + L"msFlipDelay should not be stored as missing (NaN)"); + + Assert::AreEqual(0.0, metrics.msCPUBusy, 0.0001); + Assert::AreEqual(0.0, metrics.msCPUWait, 0.0001); + Assert::AreEqual(0.0, metrics.msCPUTime, 0.0001); + Assert::AreEqual(0.0, metrics.msGPULatency, 0.0001); + Assert::AreEqual(0.0, metrics.msGPUBusy, 0.0001); + Assert::AreEqual(0.0, metrics.msGPUWait, 0.0001); + Assert::AreEqual(0.0, metrics.msGPUTime, 0.0001); + Assert::AreEqual(0.0, metrics.msVideoBusy, 0.0001); + + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msClickToPhotonLatency), + L"msClickToPhotonLatency should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msAllInputPhotonLatency), + L"msAllInputPhotonLatency should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msInstrumentedInputTime), + L"msInstrumentedInputTime should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msAnimationError), + L"msAnimationError should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msAnimationTime), + L"msAnimationTime should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msInstrumentedSleep), + L"msInstrumentedSleep should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msInstrumentedGpuLatency), + L"msInstrumentedGpuLatency should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msBetweenSimStarts), + L"msBetweenSimStarts should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msInstrumentedRenderLatency), + L"msInstrumentedRenderLatency should be stored as missing (NaN)"); + Assert::IsTrue(IsMissingFrameMetricValue(metrics.msInstrumentedLatency), + L"msInstrumentedLatency should be stored as missing (NaN)"); + }; + + auto generatedRows = ComputeMetricsForPresent(qpc, frameA, nullptr, chain); + + Assert::AreEqual(size_t(3), generatedRows.size(), L"Frame A should emit only generated rows before the trailing Application row is finalized."); + assertGeneratedDisplayOnlyRow(generatedRows[0], 10); + assertGeneratedDisplayOnlyRow(generatedRows[1], 20); + assertGeneratedDisplayOnlyRow(generatedRows[2], 30); + Assert::IsTrue(chain.lastAppPresent.has_value()); + Assert::AreEqual(priorApp.presentStartTime, chain.lastAppPresent->presentStartTime, + L"lastAppPresent must not advance while only generated rows are emitted."); + Assert::AreEqual(uint64_t(5), chain.lastDisplayedScreenTime, + L"lastDisplayedScreenTime must remain on the prior Application frame until finalization."); + + auto finalizedRows = ComputeMetricsForPresent(qpc, frameA, &frameB, chain); + + Assert::AreEqual(size_t(1), finalizedRows.size(), L"Frame A should emit only the postponed trailing Application row when Frame B finalizes it."); + + const auto& finalizedMetrics = finalizedRows[0].metrics; + Assert::IsTrue(finalizedMetrics.frameType == FrameType::Application); + Assert::AreEqual(uint64_t(40), finalizedMetrics.screenTimeQpc); + Assert::IsTrue(finalizedMetrics.msDisplayLatency > 0.0); + Assert::IsTrue(finalizedMetrics.msDisplayedTime > 0.0); + Assert::IsTrue(finalizedMetrics.msUntilDisplayed > 0.0); + Assert::IsTrue(finalizedMetrics.msBetweenDisplayChange > 0.0); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msReadyTimeToDisplayLatency)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msFlipDelay)); + Assert::IsTrue(finalizedMetrics.msCPUBusy > 0.0); + Assert::IsTrue(finalizedMetrics.msCPUTime > 0.0); + Assert::IsTrue(finalizedMetrics.msGPUBusy > 0.0); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msClickToPhotonLatency)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msAllInputPhotonLatency)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msInstrumentedInputTime)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msAnimationError)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msAnimationTime)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msInstrumentedLatency)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msInstrumentedRenderLatency)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msInstrumentedSleep)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msInstrumentedGpuLatency)); + Assert::IsFalse(IsMissingFrameMetricValue(finalizedMetrics.msBetweenSimStarts)); + Assert::IsTrue(chain.lastAppPresent.has_value()); + Assert::AreEqual(frameA.presentStartTime, chain.lastAppPresent->presentStartTime, + L"lastAppPresent must advance only after the trailing Application row is finalized."); + Assert::AreEqual(uint64_t(40), chain.lastDisplayedScreenTime, + L"lastDisplayedScreenTime should advance when the trailing Application row finalizes."); + } }; TEST_CLASS(DisplayedDroppedDisplayedSequenceTests) { @@ -2082,7 +2429,7 @@ TEST_CLASS(ComputeMetricsForPresentTests) Assert::AreEqual(0.0, m.msBetweenDisplayChange, 0.0001); } - TEST_METHOD(MultipleDisplays_EachComputesDeltaFromPrior) + TEST_METHOD(MultipleDisplays_EachComputesDeltaFromPreviousDisplayedEntry) { QpcConverter qpc(10'000'000, 0); SwapChainCoreState chain{}; @@ -2093,9 +2440,9 @@ TEST_CLASS(ComputeMetricsForPresentTests) frame.timeInPresent = 50'000; frame.readyTime = 5'100'000; frame.finalState = PresentResult::Presented; - frame.displayed.PushBack({ FrameType::Application, 5'500'000 }); - frame.displayed.PushBack({ FrameType::Repeated, 5'800'000 }); - frame.displayed.PushBack({ FrameType::Repeated, 6'100'000 }); + frame.displayed.PushBack({ FrameType::Intel_XEFG, 5'500'000 }); + frame.displayed.PushBack({ FrameType::Intel_XEFG, 5'800'000 }); + frame.displayed.PushBack({ FrameType::Application, 6'100'000 }); FrameData next{}; next.finalState = PresentResult::Presented; @@ -2107,13 +2454,13 @@ TEST_CLASS(ComputeMetricsForPresentTests) double expected0 = qpc.DeltaUnsignedMilliSeconds(3'000'000, 5'500'000); Assert::AreEqual(expected0, results1[0].metrics.msBetweenDisplayChange, 0.0001); - double expected1 = qpc.DeltaUnsignedMilliSeconds(3'000'000, 5'800'000); + double expected1 = qpc.DeltaUnsignedMilliSeconds(5'500'000, 5'800'000); Assert::AreEqual(expected1, results1[1].metrics.msBetweenDisplayChange, 0.0001); auto results2 = ComputeMetricsForPresent(qpc, frame, &next, chain); Assert::AreEqual(size_t(1), results2.size()); - double expected2 = qpc.DeltaUnsignedMilliSeconds(3'000'000, 6'100'000); + double expected2 = qpc.DeltaUnsignedMilliSeconds(5'800'000, 6'100'000); Assert::AreEqual(expected2, results2[0].metrics.msBetweenDisplayChange, 0.0001); } }; diff --git a/PresentData/Debug.cpp b/PresentData/Debug.cpp index 4f8737d3..b364b9d1 100644 --- a/PresentData/Debug.cpp +++ b/PresentData/Debug.cpp @@ -288,6 +288,7 @@ void FlushModifiedPresent() FLUSH_MEMBER(PrintBool, WaitingForFlipFrameType) FLUSH_MEMBER(PrintBool, DoneWaitingForFlipFrameType) FLUSH_MEMBER(PrintBool, WaitingForFrameId) + FLUSH_MEMBER(PrintBool, DisplayedViaFlipFrameType) #undef FLUSH_MEMBER // Displayed diff --git a/PresentData/ETW/Intel_PresentMon.h b/PresentData/ETW/Intel_PresentMon.h index d4e38748..33f35cff 100644 --- a/PresentData/ETW/Intel_PresentMon.h +++ b/PresentData/ETW/Intel_PresentMon.h @@ -41,6 +41,7 @@ EVENT_DESCRIPTOR_DECL(AppSimulationStart_Info, 0x0034, 0x00, 0x00, 0x04, 0x00, 0 EVENT_DESCRIPTOR_DECL(AppSleepEnd_Info, 0x0033, 0x00, 0x00, 0x04, 0x00, 0x0033, 0x0000000000000020); EVENT_DESCRIPTOR_DECL(AppSleepStart_Info, 0x0032, 0x00, 0x00, 0x04, 0x00, 0x0032, 0x0000000000000020); EVENT_DESCRIPTOR_DECL(FlipFrameType_Info, 0x0002, 0x00, 0x00, 0x04, 0x00, 0x0002, 0x0000000000000001); +EVENT_DESCRIPTOR_DECL(FlipFrameType_Info_2, 0x0002, 0x01, 0x00, 0x04, 0x00, 0x0002, 0x0000000000000001); EVENT_DESCRIPTOR_DECL(MeasuredInput_Info, 0x000a, 0x00, 0x00, 0x04, 0x00, 0x000a, 0x0000000000000002); EVENT_DESCRIPTOR_DECL(MeasuredScreenChange_Info, 0x000b, 0x00, 0x00, 0x04, 0x00, 0x000b, 0x0000000000000002); EVENT_DESCRIPTOR_DECL(PresentFrameType_Info, 0x0001, 0x00, 0x00, 0x04, 0x00, 0x0001, 0x0000000000000001); @@ -117,6 +118,14 @@ struct FlipFrameType_Info_Props { FrameType FrameType; }; +struct FlipFrameType_Info_2_Props { + uint32_t VidPnSourceId; + uint32_t LayerIndex; + uint64_t PresentId; + FrameType FrameType; + uint64_t TimeStamp; +}; + struct PresentFrameType_Info_Props { uint32_t FrameId; FrameType FrameType; diff --git a/PresentData/PresentMonTraceConsumer.cpp b/PresentData/PresentMonTraceConsumer.cpp index a48db047..aaf01168 100644 --- a/PresentData/PresentMonTraceConsumer.cpp +++ b/PresentData/PresentMonTraceConsumer.cpp @@ -55,6 +55,28 @@ static inline bool HasScreenTime(std::shared_ptr const& p) return false; } +static inline bool HasDisplayedFrameType(std::shared_ptr const& p, FrameType frameType) +{ + for (auto const& displayed : p->Displayed) { + if (displayed.first == frameType) { + return true; + } + } + return false; +} + +static inline bool ShouldAppendApplicationAfterGeneratedDisplay(std::shared_ptr const& p) +{ + bool hasGeneratedFrame = + HasDisplayedFrameType(p, FrameType::Intel_XEFG) || + HasDisplayedFrameType(p, FrameType::AMD_AFMF); + + bool hasApplicationFrame = + HasDisplayedFrameType(p, FrameType::Application); + + return hasGeneratedFrame && !hasApplicationFrame; +} + // Set a ScreenTime for this present. // // If a ScreenTime has not yet been set, add it to Displayed and set Presented. @@ -186,6 +208,7 @@ PresentEvent::PresentEvent() , WaitingForFlipFrameType(false) , DoneWaitingForFlipFrameType(false) , WaitingForFrameId(false) + , DisplayedViaFlipFrameType(false) { } @@ -261,6 +284,7 @@ PresentEvent::PresentEvent(uint32_t fid) , WaitingForFlipFrameType(false) , DoneWaitingForFlipFrameType(false) , WaitingForFrameId(false) + , DisplayedViaFlipFrameType(false) { } @@ -1098,6 +1122,18 @@ void PMTraceConsumer::HandleDXGKEvent(EVENT_RECORD* pEventRecord) if (pEvent->FinalState != PresentResult::Presented) { VerboseTraceBeforeModifyingPresent(pEvent.get()); SetScreenTime(pEvent, hdr.TimeStamp.QuadPart); + } else if (pEvent->DisplayedViaFlipFrameType && ShouldAppendApplicationAfterGeneratedDisplay(pEvent)) { + // Special case for FlipFrameType_Info-based driver frame generation: + // ApplyFlipFrameType() may have already appended a generated frame + // which sets FinalState=Presented on the present. + // In that case, this HSync/VSync MPO completion is the application frame + // reaching the screen and should be appended as FrameType::Application. + // This check is intentionally gated on DisplayedViaFlipFrameType to + // avoid incorrectly appending a frame when PresentFrameType_Info is used + // instead (where the VSync event simply fills in the generated frame's + // display timestamp rather than signaling a separate application frame). + VerboseTraceBeforeModifyingPresent(pEvent.get()); + pEvent->Displayed.emplace_back(FrameType::NotSet, hdr.TimeStamp.QuadPart); } // Complete the present. @@ -1642,7 +1678,7 @@ void PMTraceConsumer::HandleWin32kEvent(EVENT_RECORD* pEventRecord) // we get multiple back to back flips and token tracking thread // ends up marking the first frame in the burst as dropped. // To fix this issue, we mark the frame as discarded only if - // the frame already doesn’t have valid ScreenTime. + // the frame already doesn’t have valid ScreenTime. if (!HasScreenTime(prevPresent)) { prevPresent->FinalState = PresentResult::Discarded; } @@ -3101,33 +3137,65 @@ void PMTraceConsumer::HandleIntelPresentMonEvent(EVENT_RECORD* pEventRecord) } } return; - case Intel_PresentMon::FlipFrameType_Info::Id: + case Intel_PresentMon::FlipFrameType_Info::Id: { if (mEnableFlipFrameTypeEvents) { - DebugAssert(pEventRecord->UserDataLength == sizeof(Intel_PresentMon::FlipFrameType_Info_Props)); + uint32_t vidPnSourceId = 0; + uint32_t layerIndex = 0; + uint64_t presentId = 0; + uint64_t timestamp = 0; + FrameType frameType = FrameType::NotSet; + uint32_t processId = pEventRecord->EventHeader.ProcessId; + uint32_t threadId = pEventRecord->EventHeader.ThreadId; + + if (pEventRecord->EventHeader.EventDescriptor.Version == 0) { + DebugAssert(pEventRecord->UserDataLength == sizeof(Intel_PresentMon::FlipFrameType_Info_Props)); + + auto props = (Intel_PresentMon::FlipFrameType_Info_Props*)pEventRecord->UserData; + vidPnSourceId = props->VidPnSourceId; + layerIndex = props->LayerIndex; + presentId = props->PresentId; + timestamp = pEventRecord->EventHeader.TimeStamp.QuadPart; + frameType = ConvertPMPFrameTypeToFrameType(props->FrameType); + } + else if (pEventRecord->EventHeader.EventDescriptor.Version == 1) { + DebugAssert(pEventRecord->UserDataLength == sizeof(Intel_PresentMon::FlipFrameType_Info_2_Props)); + auto props = (Intel_PresentMon::FlipFrameType_Info_2_Props*)pEventRecord->UserData; + vidPnSourceId = props->VidPnSourceId; + layerIndex = props->LayerIndex; + presentId = props->PresentId; + frameType = ConvertPMPFrameTypeToFrameType(props->FrameType); + timestamp = props->TimeStamp; + } else { + // Unknown version + return; + } - auto props = (Intel_PresentMon::FlipFrameType_Info_Props*) pEventRecord->UserData; - auto timestamp = pEventRecord->EventHeader.TimeStamp.QuadPart; - auto frameType = ConvertPMPFrameTypeToFrameType(props->FrameType); + // For now if timestamp is zero simply return + if (timestamp == 0) { + return; + } // Look up the present associated with this (VidPnSourceId, LayerIndex, PresentId). // // It is possible to see the FlipFrameType event before the MMIOFlipMultiPlaneOverlay3_Info // event, in which case the lookup will fail. In this case we deferr application of the // FlipFrameType until we see the MMIOFlipMultiPlaneOverlay3_Info event. - auto vidPnLayerId = GenerateVidPnLayerId(props->VidPnSourceId, props->LayerIndex); + auto vidPnLayerId = GenerateVidPnLayerId(vidPnSourceId, layerIndex); auto ii = mPresentByVidPnLayerId.find(vidPnLayerId); if (ii == mPresentByVidPnLayerId.end()) { - DeferFlipFrameType(vidPnLayerId, props->PresentId, timestamp, frameType); + DeferFlipFrameType(vidPnLayerId, presentId, timestamp, frameType, processId, threadId); return; } auto present = ii->second; auto jj = present->PresentIds.find(vidPnLayerId); - if (jj == present->PresentIds.end() || jj->second != props->PresentId) { - DeferFlipFrameType(vidPnLayerId, props->PresentId, timestamp, frameType); - } else { + if (jj == present->PresentIds.end() || jj->second != presentId) { + DeferFlipFrameType(vidPnLayerId, presentId, timestamp, frameType, processId, threadId); + } + else { ApplyFlipFrameType(present, timestamp, frameType); } + } } return; } @@ -3381,15 +3449,47 @@ void PMTraceConsumer::DeferFlipFrameType( uint64_t vidPnLayerId, uint64_t presentId, uint64_t timestamp, - FrameType frameType) + FrameType frameType, + uint32_t processId, + uint32_t threadId) { - DebugAssert(mPendingFlipFrameTypeEvents.find(vidPnLayerId) == mPendingFlipFrameTypeEvents.end()); + // If timestamp is 0 it means the frame was generated to be presented but did not actually get presented, + // so we should not defer the frame type. + if (timestamp == 0) { + return; + } - FlipFrameTypeEvent e; - e.PresentId = presentId; - e.Timestamp = timestamp; - e.FrameType = frameType; - mPendingFlipFrameTypeEvents.emplace(vidPnLayerId, e); + FlipFrameTypeEvent pendingEvent; + pendingEvent.PresentId = presentId; + pendingEvent.Timestamp = timestamp; + pendingEvent.FrameType = frameType; + pendingEvent.ProcessId = processId; + pendingEvent.ThreadId = threadId; + + auto [pendingFlipFrameTypeEventIt, inserted] = mPendingFlipFrameTypeEvents.try_emplace(vidPnLayerId, pendingEvent); + if (!inserted) { + auto const& existingEvent = pendingFlipFrameTypeEventIt->second; + if (existingEvent == pendingEvent) { + pmlog_info( + "Received multiple FlipFrameType events for the same" + " VidPnSourceId: " + std::to_string(vidPnLayerId >> 32) + + " LayerIndex: " + std::to_string(vidPnLayerId & 0xFFFFFFFF) + + " with PresentId: " + std::to_string(presentId) + + " for ProcessId: " + std::to_string(processId) + + " with ThreadId: " + std::to_string(threadId) + + ". Ignoring this FlipFrameType event."); + return; + } + + pmlog_info( + "Received a FlipFrameType event for VidPnSourceId: " + std::to_string(vidPnLayerId >> 32) + + " LayerIndex: " + std::to_string(vidPnLayerId & 0xFFFFFFFF) + + " with PresentId: " + std::to_string(presentId) + + " from ProcessId: " + std::to_string(processId) + + " with ThreadId: " + std::to_string(threadId) + + ". Overwriting the pending FlipFrameType event with the new one."); + pendingFlipFrameTypeEventIt->second = pendingEvent; + } } void PMTraceConsumer::ApplyFlipFrameType( @@ -3402,11 +3502,13 @@ void PMTraceConsumer::ApplyFlipFrameType( for (auto p2 : present->DependentPresents) { if (p2->FinalState != PresentResult::Discarded) { VerboseTraceBeforeModifyingPresent(p2.get()); + p2->DisplayedViaFlipFrameType = true; SetScreenTime(p2, timestamp, frameType); } } VerboseTraceBeforeModifyingPresent(present.get()); + present->DisplayedViaFlipFrameType = true; SetScreenTime(present, timestamp, frameType); } diff --git a/PresentData/PresentMonTraceConsumer.hpp b/PresentData/PresentMonTraceConsumer.hpp index cf547613..c16a146e 100644 --- a/PresentData/PresentMonTraceConsumer.hpp +++ b/PresentData/PresentMonTraceConsumer.hpp @@ -117,9 +117,20 @@ struct PresentFrameTypeEvent { }; struct FlipFrameTypeEvent { - uint64_t PresentId; - uint64_t Timestamp; - FrameType FrameType; + uint64_t PresentId = 0; + uint64_t Timestamp = 0; + FrameType FrameType = FrameType::NotSet; + uint32_t ProcessId = 0; + uint32_t ThreadId = 0; + + bool operator==(FlipFrameTypeEvent const& other) const + { + return PresentId == other.PresentId && + Timestamp == other.Timestamp && + FrameType == other.FrameType && + ProcessId == other.ProcessId && + ThreadId == other.ThreadId; + } }; // Structure used to track application provided timing information @@ -268,6 +279,12 @@ struct PresentEvent { bool WaitingForFlipFrameType; bool DoneWaitingForFlipFrameType; + // If DisplayedViaFlipFrameType, this present had a generated frame display set via + // ApplyFlipFrameType() (i.e., from a FlipFrameType_Info event). This distinguishes it from + // presents annotated via PresentFrameType_Info, where the VSync event should NOT append an + // additional application frame. + bool DisplayedViaFlipFrameType; + // If WaitingForFrameId, the present is waiting for another present with the same FrameId (or, // until a PresentFrameType_Info event with a different FrameId). bool WaitingForFrameId; @@ -598,7 +615,7 @@ struct PMTraceConsumer void UpdateReadyCount(bool useLock); - void DeferFlipFrameType(uint64_t vidPnLayerId, uint64_t presentId, uint64_t timestamp, FrameType frameType); + void DeferFlipFrameType(uint64_t vidPnLayerId, uint64_t presentId, uint64_t timestamp, FrameType frameType, uint32_t processId, uint32_t threadId); void ApplyFlipFrameType(std::shared_ptr const& present, uint64_t timestamp, FrameType frameType); void ApplyPresentFrameType(std::shared_ptr const& present); void SetAppTimingData(const EVENT_RECORD* pEventRecord); diff --git a/PresentData/PresentMonTraceSession.cpp b/PresentData/PresentMonTraceSession.cpp index 478fd49d..8e2c5254 100644 --- a/PresentData/PresentMonTraceSession.cpp +++ b/PresentData/PresentMonTraceSession.cpp @@ -939,7 +939,9 @@ ULONG EnableProvidersListing( provider.ClearFilter(); if (pmConsumer->mTrackFrameType) { provider.AddEvent(); + provider.AddEvent(); provider.AddEvent(); + provider.AddEvent(); } if (pmConsumer->mTrackPMMeasurements) { provider.AddEvent(); diff --git a/Provider/Intel-PresentMon.man b/Provider/Intel-PresentMon.man index f7b2def4..c9b01f0f 100644 Binary files a/Provider/Intel-PresentMon.man and b/Provider/Intel-PresentMon.man differ diff --git a/Provider/PresentMonProvider.cpp b/Provider/PresentMonProvider.cpp index afa22f52..912823c5 100644 --- a/Provider/PresentMonProvider.cpp +++ b/Provider/PresentMonProvider.cpp @@ -45,6 +45,7 @@ enum Event { Event_PresentFrameType, Event_PresentFrameTypeV2, Event_FlipFrameType, + Event_FlipFrameTypeV2, Event_MeasuredInput, Event_MeasuredScreenChange, Event_AppSleepStart, @@ -66,6 +67,7 @@ static EVENT_DESCRIPTOR const EventDescriptor[] = { { ID_PresentFrameType, 0, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_PresentFrameType, Keyword_FrameTypes }, { ID_PresentFrameType, 1, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_PresentFrameType, Keyword_FrameTypes }, { ID_FlipFrameType, 0, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_FlipFrameType, Keyword_FrameTypes }, + { ID_FlipFrameType, 1, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_FlipFrameType, Keyword_FrameTypes }, { ID_MeasuredInput, 0, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_MeasuredInput, Keyword_Measurements }, { ID_MeasuredScreenChange, 0, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_MeasuredScreenChange, Keyword_Measurements }, { ID_AppSleepStart, 0, 0, TRACE_LEVEL_INFORMATION, EVENT_TRACE_TYPE_INFO, ID_AppSleepStart, Keyword_Application }, @@ -290,6 +292,23 @@ ULONG PresentMonProvider_FlipFrameType( (uint8_t) frameType); } +ULONG PresentMonProvider_FlipFrameType(PresentMonProvider* ctxt, + uint32_t vidPnSourceId, + uint32_t layerIndex, + uint64_t presentId, + PresentMonProvider_FrameType frameType, + uint64_t timeStamp) +{ + PRESENTMONPROVIDER_ASSERT(ctxt != nullptr); + PRESENTMONPROVIDER_ASSERT(IsValid(frameType)); + + return WriteEvent(ctxt, Event_FlipFrameTypeV2, vidPnSourceId, + layerIndex, + presentId, + (uint8_t) frameType, + timeStamp); +} + ULONG PresentMonProvider_MeasuredInput( PresentMonProvider* ctxt, PresentMonProvider_InputType inputType, diff --git a/Provider/PresentMonProvider.h b/Provider/PresentMonProvider.h index bf8fff39..78b41ec5 100644 --- a/Provider/PresentMonProvider.h +++ b/Provider/PresentMonProvider.h @@ -88,6 +88,13 @@ ULONG PresentMonProvider_FlipFrameType(PresentMonProvider* ctxt, uint64_t presentId, PresentMonProvider_FrameType frameType); +ULONG PresentMonProvider_FlipFrameType(PresentMonProvider* ctxt, + uint32_t vidPnSourceId, + uint32_t layerIndex, + uint64_t presentId, + PresentMonProvider_FrameType frameType, + uint64_t timeStamp); + // MEASURED INPUT/PHOTON LATENCY // // These provide times associated with user input and monitor updates that were measured using some