[x265] [PATCH 05 of 13] stats: keep timestamps instead of elapsed times, to allow more flexibility

[Steve Borho]

# HG changeset patch
# User Steve Borho <steve at borho.org>
# Date 1422469729 21600
#      Wed Jan 28 12:28:49 2015 -0600
# Node ID 0c5078dfd9c552d3788f5d8cafb13095000169f0
# Parent  b1a2ed9bc3b4e1c55b1e93a41403830cc3cd2341
stats: keep timestamps instead of elapsed times, to allow more flexibility

diff -r b1a2ed9bc3b4 -r 0c5078dfd9c5 source/encoder/encoder.cpp
--- a/source/encoder/encoder.cpp	Wed Jan 28 12:07:53 2015 -0600
+++ b/source/encoder/encoder.cpp	Wed Jan 28 12:28:49 2015 -0600
@@ -1184,8 +1184,13 @@
                 if (numLists == 1)
                     fputs(", -", m_csvfpt);
             }
+
+#define ELAPSED_SEC(start, end) (((double)(end) - (start)) / 1000000)
+
             // detailed frame statistics
-            fprintf(m_csvfpt, ", %.3lf, %.3lf", curEncoder->m_frameTime, curEncoder->m_elapsedCompressTime);
+            fprintf(m_csvfpt, ", %.3lf, %.3lf",
+                ELAPSED_SEC(curEncoder->m_startCompressTime, curEncoder->m_endCompressTime),
+                ELAPSED_SEC(0, curEncoder->m_totalWorkerElapsedTime));
             if (curEncoder->m_totalActiveWorkerCount)
                 fprintf(m_csvfpt, ", %.3lf", (double)curEncoder->m_totalActiveWorkerCount / curEncoder->m_activeWorkerCountSamples);
             else
diff -r b1a2ed9bc3b4 -r 0c5078dfd9c5 source/encoder/frameencoder.cpp
--- a/source/encoder/frameencoder.cpp	Wed Jan 28 12:07:53 2015 -0600
+++ b/source/encoder/frameencoder.cpp	Wed Jan 28 12:28:49 2015 -0600
@@ -42,7 +42,7 @@
     : WaveFront(NULL)
     , m_threadActive(true)
 {
-    m_totalTime = 0;
+    m_totalWorkerElapsedTime = 0;
     m_frameEncoderID = 0;
     m_activeWorkerCount = 0;
     m_bAllRowsStop = false;
@@ -234,15 +234,16 @@
 void FrameEncoder::compressFrame()
 {
     ProfileScopeEvent(frameThread);
-    int64_t startCompressTime = x265_mdate();
-    Slice* slice = m_frame->m_encData->m_slice;
 
+    m_startCompressTime = x265_mdate();
     m_totalActiveWorkerCount = 0;
     m_activeWorkerCountSamples = 0;
+    m_totalWorkerElapsedTime = 0;
 
     /* Emit access unit delimiter unless this is the first frame and the user is
      * not repeating headers (since AUD is supposed to be the first NAL in the access
      * unit) */
+    Slice* slice = m_frame->m_encData->m_slice;
     if (m_param->bEnableAccessUnitDelimiters && (m_frame->m_poc || m_param->bRepeatHeaders))
     {
         m_bs.resetBits();
@@ -473,7 +474,8 @@
     }
     m_accessUnitBits = bytes << 3;
 
-    m_elapsedCompressTime = (double)(x265_mdate() - startCompressTime) / 1000000;
+    m_endCompressTime = x265_mdate();
+
     /* rateControlEnd may also block for earlier frames to call rateControlUpdateStats */
     if (m_top->m_rateControl->rateControlEnd(m_frame, m_accessUnitBits, &m_rce, &m_frameStats) < 0)
         m_top->m_aborted = true;
@@ -517,6 +519,8 @@
             ATOMIC_DEC(&refpic->m_countRefEncoders);
         }
     }
+
+    m_endFrameTime = x265_mdate();
 }
 
 void FrameEncoder::encodeSlice()
@@ -629,10 +633,13 @@
             }
 
             enableRowEncoder(row);
-            if (row == 0)
+            if (row)
+                m_pool->pokeIdleThread();
+            else
+            {
+                m_row0WaitTime = x265_mdate();
                 enqueueRowEncoder(0);
-            else
-                m_pool->pokeIdleThread();
+            }
         }
 
         m_completionEvent.wait();
@@ -663,6 +670,8 @@
                     }
                 }
 
+                if (!i)
+                    m_row0WaitTime = x265_mdate();
                 processRowEncoder(i, *m_tld);
             }
 
@@ -671,8 +680,6 @@
                 m_frameFilter.processRow(i - m_filterRowDelay);
         }
     }
-    m_frameTime = (double)m_totalTime / 1000000;
-    m_totalTime = 0;
 }
 
 void FrameEncoder::processRow(int row, int threadId)
@@ -930,7 +937,7 @@
         {
             curRow.active = false;
             curRow.busy = false;
-            m_totalTime += x265_mdate() - startTime;
+            m_totalWorkerElapsedTime += x265_mdate() - startTime; // not thread safe, but good enough
             return;
         }
     }
@@ -986,7 +993,7 @@
         }
     }
 
-    m_totalTime += x265_mdate() - startTime;
+    m_totalWorkerElapsedTime += x265_mdate() - startTime; // not thread safe, but good enough
     curRow.busy = false;
 }
 
diff -r b1a2ed9bc3b4 -r 0c5078dfd9c5 source/encoder/frameencoder.h
--- a/source/encoder/frameencoder.h	Wed Jan 28 12:07:53 2015 -0600
+++ b/source/encoder/frameencoder.h	Wed Jan 28 12:28:49 2015 -0600
@@ -163,12 +163,14 @@
     StatisticLog             m_sliceTypeLog[3];     // per-slice type CU statistics
     FrameStats               m_frameStats;          // stats of current frame for multi-pass encodes
 
-    double                   m_elapsedCompressTime;      // elapsed time spent in worker threads
-    double                   m_frameTime;                // wall time from frame start to finish
     volatile int             m_activeWorkerCount;        // count of workers current encoding or filtering CTUs
     volatile int             m_totalActiveWorkerCount;   // sum of m_activeWorkerCount sampled at end of each CTU
     volatile int             m_activeWorkerCountSamples; // count of times m_activeWorkerCount was sampled (think vbv restarts)
-    int64_t                  m_totalTime;
+    int64_t                  m_startCompressTime;        // timestamp when frame encoder is given a frame
+    int64_t                  m_row0WaitTime;             // timestamp when row 0 is allowed to start
+    int64_t                  m_endCompressTime;          // timestamp after all CTUs are compressed
+    int64_t                  m_endFrameTime;             // timestamp after RCEnd, NR updates, etc
+    int64_t                  m_totalWorkerElapsedTime;
 
     Encoder*                 m_top;
     x265_param*              m_param;