Rename PresentEvent::QpcTime and TimeTaken to PresentStartTime and Pr…

…esentStopTime

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

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

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<PresentEvent> 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<PresentEvent> 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<PresentEvent> 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<PresentEvent> PMTraceConsumer::FindOrCreatePresent(EVENT_HEADER
         present = std::make_shared<PresentEvent>();
 
         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<PresentEvent>();
 
     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) {

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<std::shared_ptr<PresentEvent>> mAllPresents;
 
     std::unordered_map<uint32_t, std::shared_ptr<PresentEvent>> mPresentByThreadId;                     // ThreadId -> PresentEvent
-    std::unordered_map<uint32_t, OrderedPresents>               mOrderedPresentsByProcessId;            // ProcessId -> ordered QpcTime -> PresentEvent
+    std::unordered_map<uint32_t, OrderedPresents>               mOrderedPresentsByProcessId;            // ProcessId -> ordered PresentStartTime -> PresentEvent
     std::unordered_map<uint32_t, std::shared_ptr<PresentEvent>> mPresentBySubmitSequence;               // SubmitSequenceId -> PresentEvent
     std::unordered_map<Win32KPresentHistoryToken, std::shared_ptr<PresentEvent>,
                        Win32KPresentHistoryTokenHash>           mPresentByWin32KPresentHistoryToken;    // Win32KPresentHistoryToken -> PresentEvent

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;
                 }
             }

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");

PresentMon/OutputThread.cpp

@@ -243,7 +243,7 @@ static void AddPresents(std::vector<std::shared_ptr<PresentEvent>> 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) {

PresentMon/PresentMon.hpp

@@ -149,5 +149,7 @@ void DequeueAnalyzedInfo(
     std::vector<std::shared_ptr<PresentEvent>>* lostPresentEvents,
     std::vector<std::shared_ptr<LateStageReprojectionEvent>>* 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);

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

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