vea_unittest: Calculate per-frame encode latency

content/common/gpu/media/video_encode_accelerator_unittest.cc

Index: content/common/gpu/media/video_encode_accelerator_unittest.cc
diff --git a/content/common/gpu/media/video_encode_accelerator_unittest.cc b/content/common/gpu/media/video_encode_accelerator_unittest.cc
index 19a9d34c25c0cbb16f2de12380f91acce7b3eaa7..b3fa2e19afe8f3be891f6fa0f525f21872fd6a35 100644
--- a/content/common/gpu/media/video_encode_accelerator_unittest.cc
+++ b/content/common/gpu/media/video_encode_accelerator_unittest.cc
@@ -2,6 +2,8 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include <algorithm>
+
 #include "base/at_exit.h"
 #include "base/bind.h"
 #include "base/command_line.h"
@@ -69,6 +71,8 @@ const uint32 kMinPerfFPS = 30;
 // The input stream will be looped as many times as needed in bitrate tests
 // to reach at least this number of frames before calculating final bitrate.
 const unsigned int kMinFramesForBitrateTests = 300;
+// The percentiles to measure for encode latency.
+static unsigned int kLoggedLatencyPercentiles[] = {50, 75, 95};
 
 // The syntax of multiple test streams is:
 //  test-stream1;test-stream2;test-stream3
@@ -189,6 +193,19 @@ static bool WriteFile(base::File* file,
   return true;
 }
 
+// Return the |percentile| from a sorted vector.
+static base::TimeDelta Percentile(
+    const std::vector<base::TimeDelta>& sorted_values,
+    unsigned int percentile) {
+  size_t size = sorted_values.size();
+  CHECK_GT(size, 0);
+  CHECK_LE(percentile, 100);
+  // Use Nearest Rank method in http://en.wikipedia.org/wiki/Percentile.
+  int index =
+      std::max(static_cast<int>(ceil(0.01f * percentile * size)) - 1, 0);
+  return sorted_values[index];
+}
+
 static bool IsH264(media::VideoCodecProfile profile) {
   return profile >= media::H264PROFILE_MIN && profile <= media::H264PROFILE_MAX;
 }
@@ -360,10 +377,12 @@ class VideoEncodeAcceleratorTestEnvironment : public ::testing::Environment {
   VideoEncodeAcceleratorTestEnvironment(
       scoped_ptr<base::FilePath::StringType> data,
       const base::FilePath& log_path,
-      bool run_at_fps)
+      bool run_at_fps,
+      bool needs_encode_latency)
       : run_at_fps_(run_at_fps),
         test_stream_data_(data.Pass()),
-        log_path_(log_path) {}
+        log_path_(log_path),
+        needs_encode_latency_(needs_encode_latency) {}
 
   virtual void SetUp() {
     if (!log_path_.empty()) {
@@ -381,16 +400,20 @@ class VideoEncodeAcceleratorTestEnvironment : public ::testing::Environment {
     log_file_.reset();
   }
 
-  // Log one entry of machine-readable data to file.
+  // Log one entry of machine-readable data to file and LOG(INFO).
   // The log has one data entry per line in the format of "<key>: <value>".
+  // Note that Chrome OS video_VEAPerf autotest parses the output key and value
+  // pairs. Be sure to keep the autotest in sync.
   void LogToFile(const std::string& key, const std::string& value) {
+    std::string s = base::StringPrintf("%s: %s\n", key.c_str(), value.c_str());
+    LOG(INFO) << s;
     if (log_file_) {
-      std::string s =
-          base::StringPrintf("%s: %s\n", key.c_str(), value.c_str());
       log_file_->WriteAtCurrentPos(s.data(), s.length());
     }
   }
 
+  bool NeedsEncodeLatency() { return needs_encode_latency_; }
+
   ScopedVector<TestStream> test_streams_;
   bool run_at_fps_;
 
@@ -398,6 +421,7 @@ class VideoEncodeAcceleratorTestEnvironment : public ::testing::Environment {
   scoped_ptr<base::FilePath::StringType> test_stream_data_;
   base::FilePath log_path_;
   scoped_ptr<base::File> log_file_;
+  bool needs_encode_latency_;

[Pawel Osciak, 2015/05/14 01:46:29]

Perhaps this should be in VEAClient, since it's the client collecting this and
for consistency with run_at_fps.

[Justin Chuang, 2015/05/14 05:16:13]

Thanks. I'm aware how run_at_fps was placed. 

For now, run_at_fps is not a per-test flag yet. Although it looks "more correct"
to define the flag in VEAClient, I prefer to remove VEAClient.run_at_fps_, add
VEATestEnvironment.RunAtFPS(), and refactor other global vars (g_fake_encoder
and g_num_frames_to_encode) into methods in VEATestEnvironment, too. Does it
sound okay (in separate CL)?

It's probably about different perspectives. When I was new to this test, I felt
this file is too big to understand quickly, and I prefer to keep it as simple as
possible, trading off other criteria. But for the initiated, complexity may not
be a good reason.

 };
 
 enum ClientState {
@@ -564,9 +588,6 @@ class VEAClient : public VideoEncodeAccelerator::Client {
   void CreateEncoder();
   void DestroyEncoder();
 
-  // Return the number of encoded frames per second.
-  double frames_per_second();
-
   // VideoDecodeAccelerator::Client implementation.
   void RequireBitstreamBuffers(unsigned int input_count,
                                const gfx::Size& input_coded_size,
@@ -579,6 +600,9 @@ class VEAClient : public VideoEncodeAccelerator::Client {
  private:
   bool has_encoder() { return encoder_.get(); }
 
+  // Return the number of encoded frames per second.
+  double frames_per_second();
+
   scoped_ptr<media::VideoEncodeAccelerator> CreateFakeVEA();
   scoped_ptr<media::VideoEncodeAccelerator> CreateV4L2VEA();
   scoped_ptr<media::VideoEncodeAccelerator> CreateVaapiVEA();
@@ -602,15 +626,17 @@ class VEAClient : public VideoEncodeAccelerator::Client {
   // and accounting. Returns false once we have collected all frames we needed.
   bool HandleEncodedFrame(bool keyframe);
 
+  // Verify the minimum FPS requirement.
+  void VerifyMinFPS();
+
   // Verify that stream bitrate has been close to current_requested_bitrate_,
   // assuming current_framerate_ since the last time VerifyStreamProperties()
   // was called. Fail the test if |force_bitrate_| is true and the bitrate
   // is not within kBitrateTolerance.
   void VerifyStreamProperties();
 
-  // Test codec performance, failing the test if we are currently running
-  // the performance test.
-  void VerifyPerf();
+  // Log the performance data.
+  void LogPerf();
 
   // Write IVF file header to test_stream_->out_filename.
   void WriteIvfFileHeader();
@@ -618,9 +644,11 @@ class VEAClient : public VideoEncodeAccelerator::Client {
   // Write an IVF frame header to test_stream_->out_filename.
   void WriteIvfFrameHeader(int frame_index, size_t frame_size);
 
-  // Prepare and return a frame wrapping the data at |position| bytes in
-  // the input stream, ready to be sent to encoder.
-  scoped_refptr<media::VideoFrame> PrepareInputFrame(off_t position);
+  // Prepare and return a frame wrapping the data at |position| bytes in the
+  // input stream, ready to be sent to encoder.
+  // The input frame id is returned in |input_id|.
+  scoped_refptr<media::VideoFrame> PrepareInputFrame(off_t position,
+                                                     int32* input_id);
 
   // Update the parameters according to |mid_stream_bitrate_switch| and
   // |mid_stream_framerate_switch|.
@@ -638,11 +666,18 @@ class VEAClient : public VideoEncodeAccelerator::Client {
   // Used to notify another thread about the state. VEAClient does not own this.
   ClientStateNotification<ClientState>* note_;
 
-  // Ids assigned to VideoFrames (start at 1 for easy comparison with
-  // num_encoded_frames_).
+  // Ids assigned to VideoFrames.
   std::set<int32> inputs_at_client_;
   int32 next_input_id_;
 
+  // Encode start time of all encoded frames. The position in the vector is the
+  // frame input id.
+  std::vector<base::TimeTicks> encode_start_time_;
+  // The encode latencies of all encoded frames. We define encode latency as the
+  // time delay from input of each VideoFrame (VEA::Encode()) to output of the
+  // corresponding BitstreamBuffer (VEA::Client::BitstreamBufferReady()).
+  std::vector<base::TimeDelta> encode_latencies_;
+
   // Ids for output BitstreamBuffers.
   typedef std::map<int32, base::SharedMemory*> IdToSHM;
   ScopedVector<base::SharedMemory> output_shms_;
@@ -699,9 +734,6 @@ class VEAClient : public VideoEncodeAccelerator::Client {
 
   scoped_ptr<StreamValidator> validator_;
 
-  // The time when the encoding started.
-  base::TimeTicks encode_start_time_;
-
   // The time when the last encoded frame is ready.
   base::TimeTicks last_frame_ready_time_;
 
@@ -907,7 +939,7 @@ void VEAClient::UpdateTestStreamData(bool mid_stream_bitrate_switch,
 }
 
 double VEAClient::frames_per_second() {

[Pawel Osciak, 2015/05/14 01:46:29]

CHECK(!encode_start_time_.empty());

[Justin Chuang, 2015/05/14 05:16:13]

Done. But please see below.

-  base::TimeDelta duration = last_frame_ready_time_ - encode_start_time_;
+  base::TimeDelta duration = last_frame_ready_time_ - encode_start_time_[0];
   return num_encoded_frames_ / duration.InSecondsF();
 }
 
@@ -924,6 +956,11 @@ void VEAClient::RequireBitstreamBuffers(unsigned int input_count,
   if (g_num_frames_to_encode > 0)
     num_frames_to_encode_ = g_num_frames_to_encode;
 
+  // Speed up vector insertion.
+  encode_start_time_.reserve(num_frames_to_encode_);
+  if (g_env->NeedsEncodeLatency())
+    encode_latencies_.reserve(num_frames_to_encode_);
+
   // We may need to loop over the stream more than once if more frames than
   // provided is required for bitrate tests.
   if (force_bitrate_ && num_frames_to_encode_ < kMinFramesForBitrateTests) {
@@ -949,7 +986,6 @@ void VEAClient::RequireBitstreamBuffers(unsigned int input_count,
     FeedEncoderWithOutput(shm);
   }
 
-  encode_start_time_ = base::TimeTicks::Now();
   if (run_at_fps_) {
     input_timer_.reset(new base::RepeatingTimer<VEAClient>());
     input_timer_->Start(
@@ -1034,7 +1070,8 @@ void VEAClient::InputNoLongerNeededCallback(int32 input_id) {
     FeedEncoderWithOneInput();
 }
 
-scoped_refptr<media::VideoFrame> VEAClient::PrepareInputFrame(off_t position) {
+scoped_refptr<media::VideoFrame> VEAClient::PrepareInputFrame(off_t position,
+                                                              int32* input_id) {
   CHECK_LE(position + test_stream_->aligned_buffer_size,
            test_stream_->mapped_aligned_in_file.length());
 
@@ -1065,8 +1102,8 @@ scoped_refptr<media::VideoFrame> VEAClient::PrepareInputFrame(off_t position) {
                          next_input_id_)));
 
   CHECK(inputs_at_client_.insert(next_input_id_).second);
-  ++next_input_id_;
 
+  *input_id = next_input_id_++;
   return frame;
 }
 
@@ -1095,16 +1132,19 @@ void VEAClient::FeedEncoderWithOneInput() {
     pos_in_input_stream_ = 0;
   }
 
+  int32 input_id;
+  scoped_refptr<media::VideoFrame> video_frame =
+      PrepareInputFrame(pos_in_input_stream_, &input_id);
+  pos_in_input_stream_ += test_stream_->aligned_buffer_size;
+
   bool force_keyframe = false;
-  if (keyframe_period_ && next_input_id_ % keyframe_period_ == 0) {
+  if (keyframe_period_ && input_id % keyframe_period_ == 0) {
     force_keyframe = true;
     ++num_keyframes_requested_;
   }
 
-  scoped_refptr<media::VideoFrame> video_frame =
-      PrepareInputFrame(pos_in_input_stream_);
-  pos_in_input_stream_ += test_stream_->aligned_buffer_size;
-
+  CHECK_EQ(input_id, static_cast<int32>(encode_start_time_.size()));
+  encode_start_time_.push_back(base::TimeTicks::Now());
   encoder_->Encode(video_frame, force_keyframe);
 }
 
@@ -1130,11 +1170,17 @@ bool VEAClient::HandleEncodedFrame(bool keyframe) {
   // return value from this method.
   CHECK_LE(num_encoded_frames_, num_frames_to_encode_);
 
+  last_frame_ready_time_ = base::TimeTicks::Now();
+
+  if (g_env->NeedsEncodeLatency()) {
+    base::TimeTicks start_time = encode_start_time_[num_encoded_frames_];

[Pawel Osciak, 2015/05/14 01:46:29]

CHECK_LT(num_encoded_frames_, encode_start_time_.size());

[Justin Chuang, 2015/05/14 05:16:13]

Vector will throw out_of_range. Shall I CHECK it again? For Python, we usually
don't do it at all and relies on runtime exception in builtin types, or there
will be many to check, and no much differences between manual checking and
runtime exceptions in types.

[Pawel Osciak, 2015/05/14 06:02:52]

Please CHECK. The terminate message for out_of_range exception won't show us
where this happened. Much easier to CHECK here.

[Justin Chuang, 2015/05/14 06:29:57]

Done.

+    CHECK(!start_time.is_null());
+    encode_latencies_.push_back(last_frame_ready_time_ - start_time);
+  }
+
   ++num_encoded_frames_;
   ++num_frames_since_last_check_;
 
-  last_frame_ready_time_ = base::TimeTicks::Now();
-
   // Because the keyframe behavior requirements are loose, we give
   // the encoder more freedom here. It could either deliver a keyframe
   // immediately after we requested it, which could be for a frame number
@@ -1169,7 +1215,8 @@ bool VEAClient::HandleEncodedFrame(bool keyframe) {
             base::Bind(&VEAClient::OnInputTimer, base::Unretained(this)));
     }
   } else if (num_encoded_frames_ == num_frames_to_encode_) {
-    VerifyPerf();
+    LogPerf();
+    VerifyMinFPS();
     VerifyStreamProperties();
     SetState(CS_FINISHED);
     return false;
@@ -1178,13 +1225,27 @@ bool VEAClient::HandleEncodedFrame(bool keyframe) {
   return true;
 }
 
-void VEAClient::VerifyPerf() {
-  double measured_fps = frames_per_second();
-  LOG(INFO) << "Measured encoder FPS: " << measured_fps;
+void VEAClient::LogPerf() {
+  // Log measured FPS.

[Pawel Osciak, 2015/05/14 01:46:29]

Comment unnecessary.

[Justin Chuang, 2015/05/14 05:16:13]

Done.

   g_env->LogToFile("Measured encoder FPS",
-                   base::StringPrintf("%.3f", measured_fps));
+                   base::StringPrintf("%.3f", frames_per_second()));
+
+  // Log encode latencies.
+  if (g_env->NeedsEncodeLatency()) {
+    std::sort(encode_latencies_.begin(), encode_latencies_.end());
+    for (const auto& percentile : kLoggedLatencyPercentiles) {
+      base::TimeDelta latency = Percentile(encode_latencies_, percentile);
+      g_env->LogToFile(
+          base::StringPrintf("Encode latency for the %dth percentile",
+                             percentile),
+          base::StringPrintf("%" PRId64 " us", latency.InMicroseconds()));
+    }
+  }
+}
+
+void VEAClient::VerifyMinFPS() {
   if (test_perf_)
-    EXPECT_GE(measured_fps, kMinPerfFPS);
+    EXPECT_GE(frames_per_second(), kMinPerfFPS);
 }
 
 void VEAClient::VerifyStreamProperties() {
@@ -1395,6 +1456,7 @@ int main(int argc, char** argv) {
   DCHECK(cmd_line);
 
   bool run_at_fps = false;
+  bool needs_encode_latency = false;
   base::FilePath log_path;
 
   base::CommandLine::SwitchMap switches = cmd_line->GetSwitches();
@@ -1416,6 +1478,10 @@ int main(int argc, char** argv) {
       CHECK(base::StringToInt(input, &content::g_num_frames_to_encode));
       continue;
     }
+    if (it->first == "encode_latency") {

[Pawel Osciak, 2015/05/14 01:46:29]

s/encode_latency/measure_latency/

[Justin Chuang, 2015/05/14 05:16:13]

Done.

+      needs_encode_latency = true;
+      continue;
+    }
     if (it->first == "fake_encoder") {
       content::g_fake_encoder = true;
       continue;
@@ -1431,11 +1497,19 @@ int main(int argc, char** argv) {
     LOG(FATAL) << "Unexpected switch: " << it->first << ":" << it->second;
   }
 
+  if (needs_encode_latency && !run_at_fps) {
+    // Encode latency can only be measured with --run_at_fps. Otherwise, we get
+    // skewed results since it may queue too many frames at once with the same
+    // encode start time.
+    LOG(FATAL) << "--encode_latency requires --run_at_fps enabled to work.";
+  }
+
   content::g_env =
       reinterpret_cast<content::VideoEncodeAcceleratorTestEnvironment*>(
           testing::AddGlobalTestEnvironment(
               new content::VideoEncodeAcceleratorTestEnvironment(
-                  test_stream_data.Pass(), log_path, run_at_fps)));
+                  test_stream_data.Pass(), log_path, run_at_fps,
+                  needs_encode_latency)));
 
   return RUN_ALL_TESTS();
 }