From c054536fab22ef87b8e5a7d100e5ef80368b87bf Mon Sep 17 00:00:00 2001
From: Cameron Gutman <aicommander@gmail.com>
Date: Tue, 25 Dec 2018 12:09:45 -0800
Subject: [PATCH] Count Pacer delay in frame stats

---
 app/streaming/video/decoder.h                        | 1 +
 app/streaming/video/ffmpeg-renderers/pacer/pacer.cpp | 6 ++++--
 app/streaming/video/ffmpeg.cpp                       | 7 +++++++
 3 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/app/streaming/video/decoder.h b/app/streaming/video/decoder.h
index 8c1a02d1..9e55f640 100644
--- a/app/streaming/video/decoder.h
+++ b/app/streaming/video/decoder.h
@@ -16,6 +16,7 @@ typedef struct _VIDEO_STATS {
     uint32_t pacerDroppedFrames;
     uint32_t totalReassemblyTime;
     uint32_t totalDecodeTime;
+    uint32_t totalPacerTime;
     uint32_t totalRenderTime;
     float receivedFps;
     float decodedFps;
diff --git a/app/streaming/video/ffmpeg-renderers/pacer/pacer.cpp b/app/streaming/video/ffmpeg-renderers/pacer/pacer.cpp
index eebc8934..c76d2f44 100644
--- a/app/streaming/video/ffmpeg-renderers/pacer/pacer.cpp
+++ b/app/streaming/video/ffmpeg-renderers/pacer/pacer.cpp
@@ -87,7 +87,6 @@ void Pacer::vsyncCallback(int timeUntilNextVsyncMillis)
         av_frame_free(&frame);
     }
 
-
     if (m_FrameQueue.isEmpty()) {
         SDL_AtomicUnlock(&m_FrameQueueLock);
 
@@ -112,8 +111,11 @@ RenderNextFrame:
     AVFrame* frame = m_FrameQueue.dequeue();
     SDL_AtomicUnlock(&m_FrameQueueLock);
 
-    // Render it
+    // Count time spent in Pacer's queues
     Uint32 beforeRender = SDL_GetTicks();
+    m_VideoStats->totalPacerTime += beforeRender - frame->pts;
+
+    // Render it
     m_VsyncRenderer->renderFrameAtVsync(frame);
     m_VideoStats->totalRenderTime += SDL_GetTicks() - beforeRender;
     m_VideoStats->renderedFrames++;
diff --git a/app/streaming/video/ffmpeg.cpp b/app/streaming/video/ffmpeg.cpp
index e9b0952f..5060ba94 100644
--- a/app/streaming/video/ffmpeg.cpp
+++ b/app/streaming/video/ffmpeg.cpp
@@ -258,6 +258,7 @@ void FFmpegVideoDecoder::addVideoStats(VIDEO_STATS& src, VIDEO_STATS& dst)
     dst.pacerDroppedFrames += src.pacerDroppedFrames;
     dst.totalReassemblyTime += src.totalReassemblyTime;
     dst.totalDecodeTime += src.totalDecodeTime;
+    dst.totalPacerTime += src.totalPacerTime;
     dst.totalRenderTime += src.totalRenderTime;
 
     Uint32 now = SDL_GetTicks();
@@ -311,6 +312,9 @@ void FFmpegVideoDecoder::logVideoStats(VIDEO_STATS& stats, const char* title)
         SDL_LogInfo(SDL_LOG_CATEGORY_APPLICATION,
                     "Average decode time: %.2f ms",
                     (float)stats.totalDecodeTime / stats.decodedFrames);
+        SDL_LogInfo(SDL_LOG_CATEGORY_APPLICATION,
+                    "Average frame pacing delay: %.2f ms",
+                    (float)stats.totalPacerTime / stats.renderedFrames);
         SDL_LogInfo(SDL_LOG_CATEGORY_APPLICATION,
                     "Average render time: %.2f ms",
                     (float)stats.totalRenderTime / stats.renderedFrames);
@@ -577,6 +581,9 @@ int FFmpegVideoDecoder::submitDecodeUnit(PDECODE_UNIT du)
         // Reset failed decodes count if we reached this far
         m_ConsecutiveFailedDecodes = 0;
 
+        // Capture a frame timestamp to measuring pacing delay
+        frame->pts = SDL_GetTicks();
+
         // Queue the frame for rendering from the main thread
         SDL_AtomicIncRef(&m_QueuedFrames);
         queueFrame(frame);