Merge pull request #319 from GameTechDev/feature/etl-backpressure

Backpressure and other options for PresentData debugging

Author: markgalvan-intel

PresentData/PresentMonTraceConsumer.cpp

@@ -1894,21 +1894,33 @@ void PMTraceConsumer::CompletePresent(std::shared_ptr<PresentEvent> const& p)
 void PMTraceConsumer::AddPresentToCompletedList(std::shared_ptr<PresentEvent> const& present)
 {
     {
-        std::lock_guard<std::mutex> lock(mPresentEventMutex);
+        std::unique_lock<std::mutex> lock(mPresentEventMutex);
 
-        // If the completed list is full, throw away the oldest completed present, if it IsLost; or this
-        // present, if it IsLost; or the oldest completed present.
         uint32_t index;
+        // if completed buffer is full
         if (mCompletedCount == PRESENTEVENT_CIRCULAR_BUFFER_SIZE) {
-            if (!mCompletedPresents[mCompletedIndex]->IsLost && present->IsLost) {
-                return;
+            // if we are in offline ETL processing mode, block instead of overwriting events
+            // unless either A) the buffer is full of non-ready events or B) backpressure disabled via CLI option
+            if (!mIsRealtimeSession && mReadyCount != 0 && !mDisableOfflineBackpressure) {
+                mCompletedRingCondition.wait(lock, [this] { return mCompletedCount < PRESENTEVENT_CIRCULAR_BUFFER_SIZE; });
+                index = GetRingIndex(mCompletedIndex + mCompletedCount);
+                mCompletedCount++;
             }
+            // Completed present overflow routine (when not blocking):
+            // If the completed list is full, throw away the oldest completed present, if it IsLost; or this
+            // present, if it IsLost; or the oldest completed present.
+            else {
+                if (!mCompletedPresents[mCompletedIndex]->IsLost && present->IsLost) {
+                    return;
+                }
 
-            index = mCompletedIndex;
-            mCompletedIndex = GetRingIndex(mCompletedIndex + 1);
-            if (mReadyCount > 0) {
-                mReadyCount--;
+                index = mCompletedIndex;
+                mCompletedIndex = GetRingIndex(mCompletedIndex + 1);
+                if (mReadyCount > 0) {
+                    mReadyCount--;
+                }
             }
+        // otherwise, completed buffer still has available space
         } else {
             index = GetRingIndex(mCompletedIndex + mCompletedCount);
             mCompletedCount++;
@@ -2384,19 +2396,20 @@ void PMTraceConsumer::DequeueProcessEvents(std::vector<ProcessEvent>& outProcess
 void PMTraceConsumer::DequeuePresentEvents(std::vector<std::shared_ptr<PresentEvent>>& outPresentEvents)
 {
     outPresentEvents.clear();
+    {
+        std::lock_guard<std::mutex> lock(mPresentEventMutex);
+        if (mReadyCount > 0) {
+            outPresentEvents.resize(mReadyCount, nullptr);
+            for (uint32_t i = 0; i < mReadyCount; ++i) {
+                std::swap(outPresentEvents[i], mCompletedPresents[mCompletedIndex]);
+                mCompletedIndex = GetRingIndex(mCompletedIndex + 1);
+            }
 
-    std::lock_guard<std::mutex> lock(mPresentEventMutex);
-
-    if (mReadyCount > 0) {
-        outPresentEvents.resize(mReadyCount, nullptr);
-        for (uint32_t i = 0; i < mReadyCount; ++i) {
-            std::swap(outPresentEvents[i], mCompletedPresents[mCompletedIndex]);
-            mCompletedIndex = GetRingIndex(mCompletedIndex + 1);
+            mCompletedCount -= mReadyCount;
+            mReadyCount = 0;
         }
-
-        mCompletedCount -= mReadyCount;
-        mReadyCount = 0;
     }
+    mCompletedRingCondition.notify_one();
 }
 
 #ifdef TRACK_PRESENT_PATHS

PresentData/PresentMonTraceConsumer.hpp

@@ -251,6 +251,8 @@ struct PMTraceConsumer
     // deferred, potentially leading to dequeued events that are missing data.
     uint64_t mDeferralTimeLimit = 0; // QPC duration
 
+    bool mIsRealtimeSession = true; // allow consumer to have different behavior for realtime vs. offline analysis
+    bool mDisableOfflineBackpressure = false;
 
     // -------------------------------------------------------------------------------------------
     // These functions can be used to filter PresentEvents by process from within the consumer.
@@ -289,6 +291,7 @@ struct PMTraceConsumer
     // Mutexs to protect consumer/dequeue access from different threads:
     std::mutex mProcessEventMutex;
     std::mutex mPresentEventMutex;
+    std::condition_variable mCompletedRingCondition;
 
 
     // EventMetadata stores the structure of ETW events to optimize subsequent property retrieval.

PresentData/PresentMonTraceSession.cpp

@@ -514,6 +514,7 @@ ULONG PMTraceSession::Start(
     mStartTimestamp.QuadPart = 0;
     mContinueProcessingBuffers = TRUE;
     mIsRealtimeSession = etlPath == nullptr;
+    mPMConsumer->mIsRealtimeSession = mIsRealtimeSession;
 
     // If we're not reading an ETL, start a realtime trace session with the
     // required providers enabled.

PresentMon/CommandLine.cpp

@@ -397,6 +397,9 @@ bool ParseCommandLine(int argc, wchar_t** argv)
     args->mMultiCsv = false;
     args->mUseV1Metrics = false;
     args->mStopExistingSession = false;
+    args->mWriteFrameId = false;
+    args->mWriteDisplayTime = false;
+    args->mDisableOfflineBackpressure = false;
 
     bool sessionNameSet  = false;
     bool csvOutputStdout = false;
@@ -456,6 +459,9 @@ bool ParseCommandLine(int argc, wchar_t** argv)
         #if PRESENTMON_ENABLE_DEBUG_TRACE
         else if (ParseArg(argv[i], L"debug_verbose_trace")) { verboseTrace = true; continue; }
         #endif
+        else if (ParseArg(argv[i], L"write_frame_id")) { args->mWriteFrameId = true; continue; }
+        else if (ParseArg(argv[i], L"write_display_time")) { args->mWriteDisplayTime = true; continue; }
+        else if (ParseArg(argv[i], L"disable_offline_backpressure")) { args->mDisableOfflineBackpressure = true; continue; }
 
         // Provided argument wasn't recognized
         else if (!(ParseArg(argv[i], L"?") || ParseArg(argv[i], L"h") || ParseArg(argv[i], L"help"))) {

PresentMon/CsvOutput.cpp

@@ -164,6 +164,12 @@ void WriteCsvHeader<FrameMetrics1>(FILE* fp)
     if (args.mTimeUnit == TimeUnit::QPC || args.mTimeUnit == TimeUnit::QPCMilliSeconds) {
         fwprintf(fp, L",QPCTime");
     }
+    if (args.mWriteDisplayTime) {
+        fwprintf(fp, L",msDisplayTime");
+    }
+    if (args.mWriteFrameId) {
+        fwprintf(fp, L",FrameId");
+    }
     fwprintf(fp, L"\n");
 
     if (args.mCSVOutput == CSVOutput::Stdout) {
@@ -232,6 +238,17 @@ void WriteCsvRow<FrameMetrics1>(
         fwprintf(fp, L",%.*lf", DBL_DIG - 1, 0.001 * pmSession.TimestampDeltaToMilliSeconds(p.PresentStartTime));
         break;
     }
+    if (args.mWriteDisplayTime) {
+        if (p.ScreenTime == 0) {
+            fwprintf(fp, L",NA");
+        }
+        else {
+            fwprintf(fp, L",%.*lf", DBL_DIG - 1, 0.001 * pmSession.TimestampToMilliSeconds(p.ScreenTime));
+        }
+    }
+    if (args.mWriteFrameId) {
+        fwprintf(fp, L",%u", p.FrameId);
+    }
     fwprintf(fp, L"\n");
 
     if (args.mCSVOutput == CSVOutput::Stdout) {
@@ -283,6 +300,12 @@ void WriteCsvHeader<FrameMetrics>(FILE* fp)
     if (args.mTrackInput) {
         fwprintf(fp, L",ClickToPhotonLatency");
     }
+    if (args.mWriteDisplayTime) {
+        fwprintf(fp, L",DisplayTimeAbs");
+    }
+    if (args.mWriteFrameId) {
+        fwprintf(fp, L",FrameId");
+    }
     fwprintf(fp, L"\n");
 }
 
@@ -360,6 +383,17 @@ void WriteCsvRow<FrameMetrics>(
             fwprintf(fp, L",%.4lf", metrics.mClickToPhotonLatency);
         }
     }
+    if (args.mWriteDisplayTime) {
+        if (p.ScreenTime == 0) {
+            fwprintf(fp, L",NA");
+        }
+        else {
+            fwprintf(fp, L",%.4lf", pmSession.TimestampToMilliSeconds(p.ScreenTime));
+        }
+    }
+    if (args.mWriteFrameId) {
+        fwprintf(fp, L",%u", p.FrameId);
+    }
     fwprintf(fp, L"\n");
 }
 

PresentMon/MainThread.cpp

@@ -259,6 +259,7 @@ int wmain(int argc, wchar_t** argv)
     pmConsumer.mTrackGPUVideo  = args.mTrackGPUVideo;
     pmConsumer.mTrackInput     = args.mTrackInput;
     pmConsumer.mTrackFrameType = args.mTrackFrameType;
+    pmConsumer.mDisableOfflineBackpressure = args.mDisableOfflineBackpressure;
 
     if (args.mTargetPid != 0) {
         pmConsumer.mFilteredProcessIds = true;

PresentMon/PresentMon.hpp

@@ -83,6 +83,9 @@ struct CommandLineArgs {
     bool mMultiCsv;
     bool mUseV1Metrics;
     bool mStopExistingSession;
+    bool mWriteFrameId;
+    bool mWriteDisplayTime;
+    bool mDisableOfflineBackpressure;
 };
 
 // Metrics computed per-frame.  Duration and Latency metrics are in milliseconds.