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..0ea65aae42fd9fc1a3dc59ff9378a838c65022aa 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 percentages of the percentiles to measure for encode latency.
+static float kLoggedLatencyPercentages[] = {0.50, 0.75, 0.95};
 
 // The syntax of multiple test streams is:
 //  test-stream1;test-stream2;test-stream3
@@ -568,9 +572,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 +584,14 @@ class VEAClient : public VideoEncodeAccelerator::Client {
  private:
   bool has_encoder() { return encoder_.get(); }
 
+  // Return the number of encoded frames per second.
+  double frames_per_second();
+
+  // Return the percentile from a sorted array.
+  static base::TimeDelta percentile(
+      const std::vector<base::TimeDelta>& sorted_values,
+      float percentage);
+
   scoped_ptr<media::VideoEncodeAccelerator> CreateFakeVEA();
   scoped_ptr<media::VideoEncodeAccelerator> CreateV4L2VEA();
   scoped_ptr<media::VideoEncodeAccelerator> CreateVaapiVEA();
@@ -622,9 +631,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 +653,16 @@ 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_;
 
+  typedef std::map<int32, base::TimeTicks> IdToTicks;
+  // A map from input frame id to the encode start time of the frame.
+  IdToTicks encode_start_time_per_frame_;

[wuchengli, 2015/05/07 05:39:09]

s/encode_start_time_per_frame_/frame_encode_start_time_/. I think "per frame" is
used when a value can be divided by different number of frames. Here the value
start time is not divided.

[Justin Chuang, 2015/05/07 08:33:45]

Done. Use a slightly different name.

+  // The encode latencies of all encoded frames.
+  std::vector<base::TimeDelta> encode_latencies_;
+
   // Ids for output BitstreamBuffers.
   typedef std::map<int32, base::SharedMemory*> IdToSHM;
   ScopedVector<base::SharedMemory> output_shms_;
@@ -915,6 +931,22 @@ double VEAClient::frames_per_second() {
   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();
+  if (size == 0) {

[Owen Lin, 2015/05/07 06:29:53]

I think we should not return 0 when size == 0. How about just let the test
crash: CHECK_NE(0, size).

[Justin Chuang, 2015/05/07 08:33:45]

Done.

+    return base::TimeDelta();
+  } else {
+    CHECK_GE(percentage, 0.0f);
+    CHECK_LE(percentage, 1.0f);
+    // Use Nearest Rank method.
+    size_t index =
+        std::min(base::checked_cast<size_t>(percentage * size), size - 1);
+    return sorted_values[index];
+  }
+}
+
 void VEAClient::RequireBitstreamBuffers(unsigned int input_count,
                                         const gfx::Size& input_coded_size,
                                         size_t output_size) {
@@ -1038,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());
 
@@ -1069,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;
 }
 
@@ -1099,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(encode_start_time_per_frame_.insert(

[wuchengli, 2015/05/07 05:39:09]

Why do we need to CHECK the return value of insert? Doesn't it always return
something?

[Owen Lin, 2015/05/07 06:29:53]

second is true iff the key wasn't in the map.

[wuchengli, 2015/05/07 07:05:20]

I see. I didn't see .second. :)

+      std::make_pair(input_id, base::TimeTicks::Now())).second);
   encoder_->Encode(video_frame, force_keyframe);
 }
 
@@ -1134,11 +1170,18 @@ 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();
+
+  // Record encode latency of this frame.
+  IdToTicks::iterator it =
+      encode_start_time_per_frame_.find(num_encoded_frames_);
+  CHECK_NE(it, encode_start_time_per_frame_.end());
+  encode_latencies_.push_back(last_frame_ready_time_ - it->second);
+  encode_start_time_per_frame_.erase(it);
+
   ++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
@@ -1183,12 +1226,27 @@ bool VEAClient::HandleEncodedFrame(bool keyframe) {
 }
 
 void VEAClient::VerifyPerf() {

[wuchengli, 2015/05/07 05:39:09]

s/VerifyPerf/LogPerf/ and move line 1234-1235 out of this function. Most of this
function logs the performance result. 

[Justin Chuang, 2015/05/07 08:33:45]

Done.

+  // Log measured FPS.
   double measured_fps = frames_per_second();
   LOG(INFO) << "Measured encoder FPS: " << measured_fps;
   g_env->LogToFile("Measured encoder FPS",
                    base::StringPrintf("%.3f", measured_fps));
   if (test_perf_)
     EXPECT_GE(measured_fps, kMinPerfFPS);
+
+  // Log encode latencies.
+  std::sort(encode_latencies_.begin(), encode_latencies_.end());
+  for (size_t i = 0; i < sizeof(kLoggedLatencyPercentages) / sizeof(float);

[wuchengli, 2015/05/07 05:39:09]

can use arraysize of base/macros.h

[Justin Chuang, 2015/05/07 08:33:45]

Done. Thanks

+       i++) {
+    float percentage_f = kLoggedLatencyPercentages[i];
+    base::TimeDelta latency = percentile(encode_latencies_, percentage_f);
+    int percentage = static_cast<int>(percentage_f * 100 + .5);

[Owen Lin, 2015/05/07 06:29:53]

After a second thought, I think we should use round instead of + .5. 

int percentage = std::round(percentage_f * 100);

In addition, static_cast is not needed to case from double to int.
(It's fine to me if you would like to keep it.)
http://www.cplusplus.com/doc/tutorial/typecasting/

[Justin Chuang, 2015/05/07 08:33:45]

I removed the typecast completely. No need to waste time on a risky casting.

+    LOG(INFO) << "Encode latency at " << percentage

[wuchengli, 2015/05/07 05:39:09]

Store the string in std::string and use it for both LOG and LogToFile.

[Justin Chuang, 2015/05/07 08:33:45]

I moved the LOG(INFO) to LogToFile(), saving a few dup lines.

+              << "%: " << latency.InMicroseconds() << " us";
+    g_env->LogToFile(

[wuchengli, 2015/05/07 05:39:09]

Add a comment saying the string have to match CrOS autotest.

[Justin Chuang, 2015/05/07 08:33:45]

Added the comment on the LogToFile() method. Thx

+        base::StringPrintf("Encode latency at %d%%", percentage),
+        base::StringPrintf("%" PRId64 " us", latency.InMicroseconds()));
+  }
 }
 
 void VEAClient::VerifyStreamProperties() {