From 094fcbc025f6f758fe503d2aa24fa0a667fa2fea Mon Sep 17 00:00:00 2001 From: Jefferson Montgomery Date: Wed, 2 Nov 2022 13:04:53 -0700 Subject: [PATCH] Rename PresentEvent::QpcTime and TimeTaken to PresentStartTime and PresentStopTime This change may impact tools using PresentData library. QpcTime->PresentStartTime is simply a rename. However, PresentStopTime is now the QPC if the present stop time. The previous TimeTaken == PresentStopTime - PresentStartTime. This change allows us to be more resilient to presents with missing present start and/or stop events. --- PresentData/Debug.cpp | 2 +- PresentData/PresentMonTraceConsumer.cpp | 34 ++++++++++++------------- PresentData/PresentMonTraceConsumer.hpp | 14 +++++----- PresentMon/Console.cpp | 4 +-- PresentMon/CsvOutput.cpp | 23 +++++++---------- PresentMon/OutputThread.cpp | 6 ++--- PresentMon/PresentMon.hpp | 2 ++ PresentMon/TraceSession.cpp | 12 +++++++++ Tests/Gold/test_case_4.csv | 2 +- 9 files changed, 54 insertions(+), 45 deletions(-) diff --git a/PresentData/Debug.cpp b/PresentData/Debug.cpp index fa4722b6..934aed5a 100644 --- a/PresentData/Debug.cpp +++ b/PresentData/Debug.cpp @@ -187,7 +187,7 @@ void FlushModifiedPresent() printf("->"); \ _Fn(gModifiedPresent->_Name); \ } - FLUSH_MEMBER(PrintTimeDelta, TimeTaken) + FLUSH_MEMBER(PrintTime, PresentStopTime) FLUSH_MEMBER(PrintTime, ReadyTime) FLUSH_MEMBER(PrintTime, ScreenTime) FLUSH_MEMBER(PrintU64x, SwapChainAddress) diff --git a/PresentData/PresentMonTraceConsumer.cpp b/PresentData/PresentMonTraceConsumer.cpp index 61cddd01..6265971e 100644 --- a/PresentData/PresentMonTraceConsumer.cpp +++ b/PresentData/PresentMonTraceConsumer.cpp @@ -30,7 +30,7 @@ uint32_t GetDeferredCompletionWaitCount(PresentEvent const& p) { // If the present was displayed or discarded before Present_Stop, defer // completion for for one Present_Stop. - if (p.Runtime != Runtime::Other && p.TimeTaken == 0) { + if (p.Runtime != Runtime::Other && p.PresentStopTime == 0) { return 1; } @@ -67,10 +67,10 @@ uint32_t GetDeferredCompletionWaitCount(PresentEvent const& p) #endif PresentEvent::PresentEvent() - : QpcTime(0) + : PresentStartTime(0) , ProcessId(0) , ThreadId(0) - , TimeTaken(0) + , PresentStopTime(0) , ReadyTime(0) , ScreenTime(0) @@ -1381,7 +1381,7 @@ void PMTraceConsumer::RemovePresentFromTemporaryTrackingCollections(std::shared_ } // mOrderedPresentsByProcessId - mOrderedPresentsByProcessId[p->ProcessId].erase(p->QpcTime); + mOrderedPresentsByProcessId[p->ProcessId].erase(p->PresentStartTime); // mPresentBySubmitSequence if (p->QueueSubmitSequence != 0) { @@ -1480,7 +1480,7 @@ void PMTraceConsumer::CompletePresentHelper(std::shared_ptr const& // Complete the present. DebugModifyPresent(p.get()); p->IsCompleted = true; - mDeferredCompletions[p->ProcessId][p->SwapChainAddress].mOrderedPresents.emplace(p->QpcTime, p); + mDeferredCompletions[p->ProcessId][p->SwapChainAddress].mOrderedPresents.emplace(p->PresentStartTime, p); // If the present is still missing some expected events, defer it's // enqueuing for some number of presents for cases where the event may @@ -1538,7 +1538,7 @@ void PMTraceConsumer::CompletePresentHelper(std::shared_ptr const& auto p2 = ii->second; ++ii; // increment iterator first as CompletePresentHelper() will remove it if (p2->SwapChainAddress == p->SwapChainAddress) { - if (p2->QpcTime >= p->QpcTime) break; + if (p2->PresentStartTime >= p->PresentStartTime) break; CompletePresentHelper(p2); } } @@ -1554,7 +1554,7 @@ void PMTraceConsumer::CompletePresent(std::shared_ptr const& p) // created but not properly tracked due to missed events. This is // especially prevalent in ETLs that start runtime providers before backend // providers and/or start capturing while an intensive graphics application - // is already running. When that happens, QpcTime/TimeTaken and + // is already running. When that happens, PresentStartTime/PresentStopTime and // ReadyTime/ScreenTime times can become mis-matched, and that offset can // persist for the full capture. // @@ -1633,14 +1633,14 @@ void PMTraceConsumer::EnqueueDeferredCompletions(DeferredCompletions* deferredCo // If later presents have already be enqueued for the user, mark this // present as lost. - if (deferredCompletions->mLastEnqueuedQpcTime > present->QpcTime) { + if (deferredCompletions->mLastEnqueuedQpcTime > present->PresentStartTime) { present->IsLost = true; } if (present->IsLost) { lostCount += 1; } else { - deferredCompletions->mLastEnqueuedQpcTime = present->QpcTime; + deferredCompletions->mLastEnqueuedQpcTime = present->PresentStartTime; completedCount += 1; } } @@ -1734,7 +1734,7 @@ std::shared_ptr PMTraceConsumer::FindOrCreatePresent(EVENT_HEADER present = std::make_shared(); DebugModifyPresent(present.get()); - present->QpcTime = *(uint64_t*) &hdr.TimeStamp; + present->PresentStartTime = *(uint64_t*) &hdr.TimeStamp; present->ProcessId = hdr.ProcessId; present->ThreadId = hdr.ThreadId; @@ -1762,7 +1762,7 @@ void PMTraceConsumer::TrackPresent( mAllPresents[mAllPresentsNextIndex] = present; mAllPresentsNextIndex = (mAllPresentsNextIndex + 1) % PRESENTEVENT_CIRCULAR_BUFFER_SIZE; - presentsByThisProcess->emplace(present->QpcTime, present); + presentsByThisProcess->emplace(present->PresentStartTime, present); SetThreadPresent(present->ThreadId, present); } @@ -1779,7 +1779,7 @@ void PMTraceConsumer::RuntimePresentStart(Runtime runtime, EVENT_HEADER const& h auto present = std::make_shared(); DebugModifyPresent(present.get()); - present->QpcTime = *(uint64_t*) &hdr.TimeStamp; + present->PresentStartTime = *(uint64_t*) &hdr.TimeStamp; present->ProcessId = hdr.ProcessId; present->ThreadId = hdr.ThreadId; present->Runtime = runtime; @@ -1804,7 +1804,7 @@ void PMTraceConsumer::RuntimePresentStop(Runtime runtime, EVENT_HEADER const& hd auto present = FindThreadPresent(hdr.ThreadId); if (present != nullptr) { // Check expected state (a new Present() that has only been started). - assert(present->TimeTaken == 0); + assert(present->PresentStopTime == 0); assert(present->IsCompleted == false); assert(present->IsLost == false); assert(present->DeferredCompletionWaitCount == 0); @@ -1841,8 +1841,8 @@ void PMTraceConsumer::RuntimePresentStop(Runtime runtime, EVENT_HEADER const& hd DebugModifyPresent(present.get()); present->DeferredCompletionWaitCount -= 1; - if (!presentStopUsed && present->TimeTaken == 0) { - present->TimeTaken = *(uint64_t*) &hdr.TimeStamp - present->QpcTime; + if (!presentStopUsed && present->PresentStopTime == 0) { + present->PresentStopTime = *(uint64_t*) &hdr.TimeStamp; if (GetDeferredCompletionWaitCount(*present) == 0) { present->DeferredCompletionWaitCount = 0; } @@ -1873,8 +1873,8 @@ void PMTraceConsumer::RuntimePresentStop(Runtime runtime, EVENT_HEADER const& hd auto present = eventIter->second; DebugModifyPresent(present.get()); - present->Runtime = runtime; - present->TimeTaken = *(uint64_t*) &hdr.TimeStamp - present->QpcTime; + present->Runtime = runtime; + present->PresentStopTime = *(uint64_t*) &hdr.TimeStamp; bool allowBatching = false; switch (runtime) { diff --git a/PresentData/PresentMonTraceConsumer.hpp b/PresentData/PresentMonTraceConsumer.hpp index 93952c9e..d5af5ff9 100644 --- a/PresentData/PresentMonTraceConsumer.hpp +++ b/PresentData/PresentMonTraceConsumer.hpp @@ -119,12 +119,12 @@ struct ProcessEvent { }; struct PresentEvent { - uint64_t QpcTime; // QPC value of the first event related to the Present (D3D9, DXGI, or DXGK Present_Start) - uint32_t ProcessId; // ID of the process that presented - uint32_t ThreadId; // ID of the thread that presented - uint64_t TimeTaken; // QPC duration between runtime present start and end - uint64_t ReadyTime; // QPC value when the last GPU commands completed prior to presentation - uint64_t ScreenTime; // QPC value when the present was displayed on screen + uint64_t PresentStartTime; // QPC value of the first event related to the Present (D3D9, DXGI, or DXGK Present_Start) + uint32_t ProcessId; // ID of the process that presented + uint32_t ThreadId; // ID of the thread that presented + uint64_t PresentStopTime; // QPC value when the application's present call completed + uint64_t ReadyTime; // QPC value when the last GPU commands completed prior to presentation + uint64_t ScreenTime; // QPC value when the present was displayed on screen // Extra present parameters obtained through DXGI or D3D9 present uint64_t SwapChainAddress; @@ -323,7 +323,7 @@ struct PMTraceConsumer std::vector> mAllPresents; std::unordered_map> mPresentByThreadId; // ThreadId -> PresentEvent - std::unordered_map mOrderedPresentsByProcessId; // ProcessId -> ordered QpcTime -> PresentEvent + std::unordered_map mOrderedPresentsByProcessId; // ProcessId -> ordered PresentStartTime -> PresentEvent std::unordered_map> mPresentBySubmitSequence; // SubmitSequenceId -> PresentEvent std::unordered_map, Win32KPresentHistoryTokenHash> mPresentByWin32KPresentHistoryToken; // Win32KPresentHistoryToken -> PresentEvent diff --git a/PresentMon/Console.cpp b/PresentMon/Console.cpp index 779b8c18..bef8d182 100644 --- a/PresentMon/Console.cpp +++ b/PresentMon/Console.cpp @@ -152,7 +152,7 @@ void UpdateConsole(uint32_t processId, ProcessInfo const& processInfo) auto const& present0 = *chain.mPresentHistory[(chain.mNextPresentIndex - chain.mPresentHistoryCount) % SwapChainData::PRESENT_HISTORY_MAX_COUNT]; auto const& presentN = *chain.mPresentHistory[(chain.mNextPresentIndex - 1) % SwapChainData::PRESENT_HISTORY_MAX_COUNT]; - auto cpuAvg = QpcDeltaToSeconds(presentN.QpcTime - present0.QpcTime) / (chain.mPresentHistoryCount - 1); + auto cpuAvg = QpcDeltaToSeconds(presentN.PresentStartTime - present0.PresentStartTime) / (chain.mPresentHistoryCount - 1); auto dspAvg = 0.0; auto latAvg = 0.0; @@ -168,7 +168,7 @@ void UpdateConsole(uint32_t processId, ProcessInfo const& processInfo) display0ScreenTime = p->ScreenTime; } displayN = p.get(); - latSum += p->ScreenTime - p->QpcTime; + latSum += p->ScreenTime - p->PresentStartTime; displayCount += 1; } } diff --git a/PresentMon/CsvOutput.cpp b/PresentMon/CsvOutput.cpp index f5e43d5d..7daa1ef7 100644 --- a/PresentMon/CsvOutput.cpp +++ b/PresentMon/CsvOutput.cpp @@ -101,26 +101,21 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven auto lastPresented = chain.mPresentHistory[(chain.mNextPresentIndex - 1) % SwapChainData::PRESENT_HISTORY_MAX_COUNT].get(); // Compute frame statistics. - double msBetweenPresents = 1000.0 * QpcDeltaToSeconds(p.QpcTime - lastPresented->QpcTime); - double msInPresentApi = 1000.0 * QpcDeltaToSeconds(p.TimeTaken); + double msBetweenPresents = 1000.0 * PositiveQpcDeltaToSeconds(lastPresented->PresentStartTime, p.PresentStartTime); + double msInPresentApi = 1000.0 * PositiveQpcDeltaToSeconds(p.PresentStartTime, p.PresentStopTime); double msUntilRenderComplete = 0.0; double msUntilDisplayed = 0.0; double msBetweenDisplayChange = 0.0; if (args.mTrackDisplay) { - if (p.ReadyTime != 0) { - if (p.ReadyTime < p.QpcTime) { - msUntilRenderComplete = -1000.0 * QpcDeltaToSeconds(p.QpcTime - p.ReadyTime); - } else { - msUntilRenderComplete = 1000.0 * QpcDeltaToSeconds(p.ReadyTime - p.QpcTime); - } - } + msUntilRenderComplete = 1000.0 * QpcDeltaToSeconds(p.PresentStartTime, p.ReadyTime); + if (presented) { - msUntilDisplayed = 1000.0 * QpcDeltaToSeconds(p.ScreenTime - p.QpcTime); + msUntilDisplayed = 1000.0 * PositiveQpcDeltaToSeconds(p.PresentStartTime, p.ScreenTime); if (chain.mLastDisplayedPresentIndex > 0) { auto lastDisplayed = chain.mPresentHistory[chain.mLastDisplayedPresentIndex % SwapChainData::PRESENT_HISTORY_MAX_COUNT].get(); - msBetweenDisplayChange = 1000.0 * QpcDeltaToSeconds(p.ScreenTime - lastDisplayed->ScreenTime); + msBetweenDisplayChange = 1000.0 * PositiveQpcDeltaToSeconds(lastDisplayed->ScreenTime, p.ScreenTime); } } } @@ -134,7 +129,7 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven p.SyncInterval, p.PresentFlags, FinalStateToDroppedString(p.FinalState), - DBL_DIG - 1, QpcToSeconds(p.QpcTime), + DBL_DIG - 1, QpcToSeconds(p.PresentStartTime), DBL_DIG - 1, msInPresentApi, DBL_DIG - 1, msBetweenPresents); if (args.mTrackDisplay) { @@ -152,9 +147,9 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven } if (args.mOutputQpcTime) { if (args.mOutputQpcTimeInSeconds) { - fprintf(fp, ",%.*lf", DBL_DIG - 1, QpcDeltaToSeconds(p.QpcTime)); + fprintf(fp, ",%.*lf", DBL_DIG - 1, QpcDeltaToSeconds(p.PresentStartTime)); } else { - fprintf(fp, ",%llu", p.QpcTime); + fprintf(fp, ",%llu", p.PresentStartTime); } } fprintf(fp, "\n"); diff --git a/PresentMon/OutputThread.cpp b/PresentMon/OutputThread.cpp index 13e38ab2..cfb572dd 100644 --- a/PresentMon/OutputThread.cpp +++ b/PresentMon/OutputThread.cpp @@ -243,7 +243,7 @@ static void AddPresents(std::vector> const& presen assert(presentEvent->IsCompleted); // Stop processing events if we hit the next stop time. - if (checkStopQpc && presentEvent->QpcTime >= stopQpc) { + if (checkStopQpc && presentEvent->PresentStartTime >= stopQpc) { *hitStopQpc = true; break; } @@ -336,7 +336,7 @@ static void PruneHistory( auto latestQpc = max(max( processEvents.empty() ? 0ull : processEvents.back().QpcTime, - presentEvents.empty() ? 0ull : presentEvents.back()->QpcTime), + presentEvents.empty() ? 0ull : presentEvents.back()->PresentStartTime), lsrEvents.empty() ? 0ull : lsrEvents.back()->QpcTime); auto minQpc = latestQpc - SecondsDeltaToQpc(2.0); @@ -350,7 +350,7 @@ static void PruneHistory( for (; count > 0; --count) { auto index = swapChain->mNextPresentIndex - count; auto const& presentEvent = swapChain->mPresentHistory[index % SwapChainData::PRESENT_HISTORY_MAX_COUNT]; - if (presentEvent->QpcTime >= minQpc) { + if (presentEvent->PresentStartTime >= minQpc) { break; } if (index == swapChain->mLastDisplayedPresentIndex) { diff --git a/PresentMon/PresentMon.hpp b/PresentMon/PresentMon.hpp index 81e2ed6d..c7bff4f6 100644 --- a/PresentMon/PresentMon.hpp +++ b/PresentMon/PresentMon.hpp @@ -149,5 +149,7 @@ void DequeueAnalyzedInfo( std::vector>* lostPresentEvents, std::vector>* lsrs); double QpcDeltaToSeconds(uint64_t qpcDelta); +double QpcDeltaToSeconds(uint64_t qpcFrom, uint64_t qpcTo); +double PositiveQpcDeltaToSeconds(uint64_t qpcFrom, uint64_t qpcTo); uint64_t SecondsDeltaToQpc(double secondsDelta); double QpcToSeconds(uint64_t qpc); diff --git a/PresentMon/TraceSession.cpp b/PresentMon/TraceSession.cpp index 336f9728..b09feb6e 100644 --- a/PresentMon/TraceSession.cpp +++ b/PresentMon/TraceSession.cpp @@ -138,6 +138,18 @@ double QpcDeltaToSeconds(uint64_t qpcDelta) return (double) qpcDelta / gSession.mQpcFrequency.QuadPart; } +double PositiveQpcDeltaToSeconds(uint64_t qpcFrom, uint64_t qpcTo) +{ + return qpcFrom == 0 || qpcTo <= qpcFrom ? 0.0 : QpcDeltaToSeconds(qpcTo - qpcFrom); +} + +double QpcDeltaToSeconds(uint64_t qpcFrom, uint64_t qpcTo) +{ + return qpcFrom == 0 || qpcTo == 0 || qpcFrom == qpcTo ? 0.0 : + qpcTo > qpcFrom ? QpcDeltaToSeconds(qpcTo - qpcFrom) : + -QpcDeltaToSeconds(qpcFrom - qpcTo); +} + uint64_t SecondsDeltaToQpc(double secondsDelta) { return (uint64_t) (secondsDelta * gSession.mQpcFrequency.QuadPart); diff --git a/Tests/Gold/test_case_4.csv b/Tests/Gold/test_case_4.csv index cc72b500..86c17893 100644 --- a/Tests/Gold/test_case_4.csv +++ b/Tests/Gold/test_case_4.csv @@ -94,7 +94,7 @@ dwm.exe,10376,0x000001BF098B1ED0,DXGI,1,0,0,2.25313540000000,0.10630000000000,16 dwm.exe,10376,0x000001BF098B1ED0,DXGI,1,0,0,2.27345740000000,0.07480000000000,20.32200000000000,0,Hardware: Legacy Flip,0.45110000000000,12.35720000000000,16.67040000000000,0,0,55454220315 Presenter.exe,5236,0x00000285B4C0D1B0,DXGI,0,0,0,2.28140790000000,2.45370000000000,15.65140000000000,0,Composed: Flip,2.45280000000000,22.44420000000000,18.03750000000000,0,1,55454299820 dwm.exe,10376,0x000001BF098B1ED0,DXGI,1,0,0,2.28631190000000,0.11240000000000,12.85450000000000,0,Hardware: Legacy Flip,0.35930000000000,17.54020000000000,18.03750000000000,0,0,55454348860 -Presenter.exe,5236,0x00000285B4C0D1B0,DXGI,0,0,0,2.29716360000000,0.24110000000000,15.75570000000000,1,Hardware: Independent Flip,5.50070000000000,5.50070000000000,1844674407370953.75000000000000,0,0,55454457377 +Presenter.exe,5236,0x00000285B4C0D1B0,DXGI,0,0,0,2.29716360000000,0.24110000000000,15.75570000000000,1,Hardware: Independent Flip,5.50070000000000,5.50070000000000,0.00000000000000,0,0,55454457377 Presenter.exe,5236,0x00000285B4C0D1B0,DXGI,0,0,0,2.31264950000000,0.30560000000000,15.48590000000000,1,Hardware: Independent Flip,0.30940000000000,0.30940000000000,10.29460000000000,0,0,55454612236 Presenter.exe,5236,0x00000285B4C0D1B0,DXGI,0,0,0,2.32834520000000,0.20100000000000,15.69570000000000,1,Hardware: Independent Flip,0.23600000000000,0.23600000000000,15.62230000000000,0,0,55454769193 Presenter.exe,5236,0x00000285B4C0D1B0,DXGI,0,0,0,2.34392200000000,0.44410000000000,15.57680000000000,1,Hardware: Independent Flip,0.48100000000000,0.48100000000000,15.82180000000000,0,0,55454924961