[x265] [PATCH 12 of 13] stats: report frame wall time spent waiting for decided frames

[Steve Borho]

# HG changeset patch
# User Steve Borho <steve at borho.org>
# Date 1422475973 21600
#      Wed Jan 28 14:12:53 2015 -0600
# Node ID 6260c3ca9f0d7b84d1b607034ca4442f534e724c
# Parent  9c26ca2c9c0e8786331e40b4ac3bce223e8e59b5
stats: report frame wall time spent waiting for decided frames

This is latency caused by the lookahead

diff -r 9c26ca2c9c0e -r 6260c3ca9f0d source/encoder/encoder.cpp
--- a/source/encoder/encoder.cpp	Wed Jan 28 13:55:42 2015 -0600
+++ b/source/encoder/encoder.cpp	Wed Jan 28 14:12:53 2015 -0600
@@ -215,7 +215,7 @@
                         fprintf(m_csvfpt, "RateFactor, ");
                     fprintf(m_csvfpt, "Y PSNR, U PSNR, V PSNR, YUV PSNR, SSIM, SSIM (dB),  List 0, List 1");
                     /* detailed performance statistics */
-                    fprintf(m_csvfpt, ", Row0Wait ms, Wall time ms, Ref Wait Wall ms, Total CTU time ms, Stall Time ms, Avg WPP, Row Blocks\n");
+                    fprintf(m_csvfpt, ", DecideWait ms, Row0Wait ms, Wall time ms, Ref Wait Wall ms, Total CTU time ms, Stall Time ms, Avg WPP, Row Blocks\n");
                 }
                 else
                     fputs(summaryCSVHeader, m_csvfpt);
@@ -1187,7 +1187,8 @@
 #define ELAPSED_MSEC(start, end) (((double)(end) - (start)) / 1000)
 
             // detailed frame statistics
-            fprintf(m_csvfpt, ", %.1lf, %.1lf, %.1lf, %.1lf, %.1lf",
+            fprintf(m_csvfpt, ", %.1lf, %.1lf, %.1lf, %.1lf, %.1lf, %.1lf",
+                ELAPSED_MSEC(0, curEncoder->m_slicetypeWaitTime),
                 ELAPSED_MSEC(curEncoder->m_startCompressTime, curEncoder->m_row0WaitTime),
                 ELAPSED_MSEC(curEncoder->m_row0WaitTime, curEncoder->m_endCompressTime),
                 ELAPSED_MSEC(curEncoder->m_row0WaitTime, curEncoder->m_allRowsAvailableTime),
diff -r 9c26ca2c9c0e -r 6260c3ca9f0d source/encoder/frameencoder.cpp
--- a/source/encoder/frameencoder.cpp	Wed Jan 28 13:55:42 2015 -0600
+++ b/source/encoder/frameencoder.cpp	Wed Jan 28 14:12:53 2015 -0600
@@ -42,7 +42,9 @@
     : WaveFront(NULL)
     , m_threadActive(true)
 {
+    m_prevOutputTime = x265_mdate();
     m_totalWorkerElapsedTime = 0;
+    m_slicetypeWaitTime = 0;
     m_frameEncoderID = 0;
     m_activeWorkerCount = 0;
     m_bAllRowsStop = false;
@@ -200,6 +202,7 @@
 
 bool FrameEncoder::startCompressFrame(Frame* curFrame)
 {
+    m_slicetypeWaitTime = x265_mdate() - m_prevOutputTime;
     m_frame = curFrame;
     curFrame->m_encData->m_frameEncoderID = m_frameEncoderID; // Each Frame knows the ID of the FrameEncoder encoding it
     curFrame->m_encData->m_slice->m_mref = m_mref;
@@ -1186,6 +1189,7 @@
         Frame *ret = m_frame;
         m_frame = NULL;
         output.takeContents(m_nalList);
+        m_prevOutputTime = x265_mdate();
         return ret;
     }
 
diff -r 9c26ca2c9c0e -r 6260c3ca9f0d source/encoder/frameencoder.h
--- a/source/encoder/frameencoder.h	Wed Jan 28 13:55:42 2015 -0600
+++ b/source/encoder/frameencoder.h	Wed Jan 28 14:12:53 2015 -0600
@@ -173,6 +173,8 @@
     int64_t                  m_endCompressTime;          // timestamp after all CTUs are compressed
     int64_t                  m_endFrameTime;             // timestamp after RCEnd, NR updates, etc
     int64_t                  m_stallStartTime;           // timestamp when worker count becomes 0
+    int64_t                  m_prevOutputTime;           // timestamp when prev frame was retrieved by API thread
+    int64_t                  m_slicetypeWaitTime;        // total elapsed time waiting for decided frame
     int64_t                  m_totalWorkerElapsedTime;   // total elapsed time spent by worker threads processing CTUs
     int64_t                  m_totalNoWorkerTime;        // total elapsed time without any active worker threads