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 52be56b5c3541aaacf2a9b6f103c7a48ea0eecef..d0d7030cfd3c9f1c5339cbf5215a6351fb44ed5c 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"
@@ -73,6 +75,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 uint32_t kLoggedLatencyPercentiles[] = {50, 75, 95};
 
 // The syntax of multiple test streams is:
 //  test-stream1;test-stream2;test-stream3
@@ -385,12 +389,14 @@ 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 Autotest parses the output key and value pairs. Be sure
+  // to keep the Autotest in sync.

[Pawel Osciak, 2015/05/11 03:43:56]

Could we have the test name for which this needs to be updated here please?

[Justin Chuang, 2015/05/11 11:24:54]

Add reference to video_VEAPerf here.

   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());
     }
   }
@@ -568,9 +574,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,
@@ -583,6 +586,19 @@ class VEAClient : public VideoEncodeAccelerator::Client {
  private:
   bool has_encoder() { return encoder_.get(); }
 
+  // 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.
+  bool needs_encode_latency() { return run_at_fps_; }

[Pawel Osciak, 2015/05/11 03:43:57]

We may not always want encode latency when we run_at_fps. We should instead have
a separate test or separate flag for enabling encode latency measurement and
forcefully enable run_at_fps for it with a warning, or refuse to run it without
it.

[Justin Chuang, 2015/05/11 11:24:54]

The problem is that run_at_fps_ is controlled by command line arg --run_at_fps,
we do not override it per test. 

If we only add encode latency as per-test flag in VideoEncodeAcceleratorTest
params and enable it in some tests, we need to add --run_at_fps  in
video_VideoEncodeAccelerator because it runs all tests. And --run_at_fps
probably should be enabled by default for users running the unittest manually.
This only complicates things.

Suggested methods are
1. Keep the current method, but add comments that run_at_fps will also measure
encode latency.
2. Add a separate command-line option to measure encode latency, and check the
dependency with --run_at_fps at main().
I'm okay for both method, but I'm not a fan of adding more command-line args.

Thoughts?

[Pawel Osciak, 2015/05/13 03:21:18]

We could if needed though, just for that test (and display a warning about
this). But just having a different "mode" activated via a flag (option 2) is
probably better.
If we had --run_at_fps by default for users running the test manually, we would
slow down the test significantly for those who didn't want to measure perf.

We regularly run the test at maximum speed without run_at_fps to run all the
other tests (basic test, keyframes, bitrates, etc.).
Option 2 sounds better to me.

[Justin Chuang, 2015/05/13 13:59:35]

Done.

+
+  // Return the number of encoded frames per second.
+  double frames_per_second();
+
+  // Return the percentile from a sorted array.

[Pawel Osciak, 2015/05/11 03:43:56]

s/percentile/|percentile|/
s/array/vector/

[Justin Chuang, 2015/05/11 11:24:54]

Done

+  static base::TimeDelta percentile(
+      const std::vector<base::TimeDelta>& sorted_values,
+      float percentage);

[Pawel Osciak, 2015/05/11 03:43:57]

s/percentage/percentile/

[Justin Chuang, 2015/05/11 11:24:54]

Done.

+
   scoped_ptr<media::VideoEncodeAccelerator> CreateFakeVEA();
   scoped_ptr<media::VideoEncodeAccelerator> CreateV4L2VEA();
   scoped_ptr<media::VideoEncodeAccelerator> CreateVaapiVEA();
@@ -606,15 +622,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();
@@ -622,9 +640,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|.
@@ -642,11 +662,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 array index is the frame input

[Pawel Osciak, 2015/05/11 03:43:57]

s/array index/position in the vector/

[Justin Chuang, 2015/05/11 11:24:54]

Done.

+  // id.
+  std::vector<base::TimeTicks> encode_start_time_;
+  // The encode latencies of all encoded frames. We define encode latency as the

[Pawel Osciak, 2015/05/11 03:43:57]

s/frames/frames in encode order/

[Justin Chuang, 2015/05/11 11:24:54]

At first, the order is irrelevant.
Then the vector will be in-place sorted by value. So I prefer not to change the
comment.

+  // 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_;
@@ -703,9 +730,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_;
 
@@ -911,10 +935,23 @@ void VEAClient::UpdateTestStreamData(bool mid_stream_bitrate_switch,
 }
 
 double VEAClient::frames_per_second() {
-  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();
 }
 
+base::TimeDelta VEAClient::percentile(
+    const std::vector<base::TimeDelta>& sorted_values,
+    float percentage) {
+  size_t size = sorted_values.size();
+  CHECK_GT(size, 0);
+  CHECK_GE(percentage, 0.0f);
+  CHECK_LE(percentage, 1.0f);
+  // Use Nearest Rank method in http://en.wikipedia.org/wiki/Percentile.
+  int32_t index =
+      std::max(static_cast<int32_t>(ceil(percentage * size)) - 1, 0);
+  return sorted_values[index];
+}
+
 void VEAClient::RequireBitstreamBuffers(unsigned int input_count,
                                         const gfx::Size& input_coded_size,
                                         size_t output_size) {
@@ -928,6 +965,11 @@ void VEAClient::RequireBitstreamBuffers(unsigned int input_count,
   if (g_num_frames_to_encode > 0)
     num_frames_to_encode_ = g_num_frames_to_encode;
 
+  // Speedup vector insertion.

[wuchengli, 2015/05/08 05:11:59]

s/Speedup/Speed up/

[Justin Chuang, 2015/05/11 11:24:54]

Done.

+  encode_start_time_.reserve(num_frames_to_encode_);
+  if (needs_encode_latency())
+    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) {
@@ -953,7 +995,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(
@@ -1038,7 +1079,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());
 
@@ -1069,8 +1111,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;
 }
 
@@ -1099,16 +1141,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);
 }
 
@@ -1134,11 +1179,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 (needs_encode_latency()) {
+    base::TimeTicks start_time = encode_start_time_[num_encoded_frames_];
+    CHECK(!start_time.is_null());
+    encode_latencies_.push_back(last_frame_ready_time_ - start_time);

[Pawel Osciak, 2015/05/11 03:43:57]

encode_latencies_ is pre-reserved at l.971, but this creates a new element at
the end enlarging it further?

[Justin Chuang, 2015/05/11 11:24:54]

No, vector::reserve() only increase the capacity, not the vector size. The
vector size is still 0 after reserve().
push_back() increments the size by 1. capacity is internal data representation
usually hidden from caller.

The reserve() call only speedup the insertion by avoiding repeated reallocation
of the internal array. (the behavior is the same with or without reserve(), only
the performance differs.)

[Pawel Osciak, 2015/05/13 03:21:18]

Acknowledged.

+  }
+
   ++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
@@ -1173,7 +1224,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;
@@ -1182,13 +1234,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.
   g_env->LogToFile("Measured encoder FPS",
-                   base::StringPrintf("%.3f", measured_fps));
+                   base::StringPrintf("%.3f", frames_per_second()));
+
+  // Log encode latencies.
+  if (needs_encode_latency()) {
+    std::sort(encode_latencies_.begin(), encode_latencies_.end());
+    for (size_t i = 0; i < arraysize(kLoggedLatencyPercentiles); i++) {

[Pawel Osciak, 2015/05/11 03:43:57]

for (const auto& p : kLoggedLatencyPercentiles) {
}

[Justin Chuang, 2015/05/11 11:24:54]

Done. Thanks. I didn't know this new style also works on C array.

+      uint32_t p = kLoggedLatencyPercentiles[i];
+      base::TimeDelta latency = percentile(encode_latencies_, 0.01f * p);
+      g_env->LogToFile(
+          base::StringPrintf("Encode latency for the %dth percentile", p),
+          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() {