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..79a1f4bbb434b524768f03b0af280bc63158ecaa 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 int32 kLoggedLatencyPercentages[] = {50, 75, 95};

[Owen Lin, 2015/05/07 09:53:45]

Please change it back to using float. We have the issue because of data
presentation.

But
1. We should not change the code just because of the data presentation.
2. We don't need those "round" and "cast" things anymore. See below.

[Justin Chuang, 2015/05/07 10:13:18]

Interesting. I'd prefer to keep the current code because
1. The array is added in this CL. So no harm to change its data format before
commit. 
2. Float => int conversion is not very comfortable although we have good helpers
and modern compiler/lib support is good. int to float is more straightforward.
Thoughts?

[Pawel Osciak, 2015/05/07 11:31:50]

s/Percentages/Percentiles/

Do we need to use int32 in particular? Just unsigned int should work? Also, as a
side note, intXX are deprecated in favor of intXX_t.

[Justin Chuang, 2015/05/08 03:57:52]

Done. also changed to uint32_t. Thx
There are other occurrences of int32 in this file. Leave it for another CL.

[Owen Lin, 2015/05/08 05:59:52]

I am OK with the code it is now. But my point is the number should be float in
its nature. It makes sense for asking for a 0.1% percentile.

We don't need float => int conversion at all. What we need is to show a float
number and that is what printf does.

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

Thanks, but my point was we didn't explicitly need a 32-bit value. Just unsigned
int should be fine.

Where we use int32 here is for the input ids, because the VDA interface still
uses int32 there.

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

Got it. Changed. I thought we're using LP64 in arm64 and x86_64, and there is no
difference between int32_t and int. But I'm fine w/ both if Chromium coding
style doesn't prefer explicit sized types.

 
 // 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 is parsing the output key and value pairs. Be

[wuchengli, 2015/05/07 09:22:17]

s/is parsing/parses/

[Justin Chuang, 2015/05/07 10:01:16]

Done.

+  // 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;

[Pawel Osciak, 2015/05/07 11:31:51]

Is this to make it convenient for humans running the test manually or to make
this visible in logs on bots as well?

[Justin Chuang, 2015/05/08 03:57:52]

for human running the test manually. (even when --output_log is not used)
Prior to this CL, another metric using LogToFile() is also output to INFO(LOG).

     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,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();
@@ -612,9 +623,8 @@ class VEAClient : public VideoEncodeAccelerator::Client {
   // 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 +632,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 +654,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;

[Pawel Osciak, 2015/05/07 11:31:50]

s/Id/InputId/

[Justin Chuang, 2015/05/08 03:57:52]

Removed this typedef after changing data structure.

+  // A map from input frame id to the encode start time of the frame.
+  IdToTicks frame_encode_start_ticks_;

[wuchengli, 2015/05/07 09:22:17]

Hmm. The name is not consistent with |encode_start_time_|, whose type is also
TimeTicks. I still prefer |frame_encode_start_times_|.

As we discussed, remove |frame_encode_start_ticks_| and make
|encode_start_time_| a vector. There's no need to erase the element of
|frame_encode_start_ticks_| in HandleEncodedFrame().

I'm not a fan of ticks in the name. "start time" is common and easier to
understand for a name. There's no need to put the type into the name.

[Justin Chuang, 2015/05/07 10:01:16]

Done. Thanks. The code looks simpler.

[Pawel Osciak, 2015/05/07 11:31:50]

Since we use input ids starting from 0 and incrementing by 1, a vector would be
enough? You could access input_id frame via vector[input_id]?

[Justin Chuang, 2015/05/08 03:57:52]

Yes, already changed in patchset 6. 

+  // The encode latencies of all encoded frames.

[Pawel Osciak, 2015/05/07 11:31:51]

We should describe how we define latency. Maybe ", i.e. time delta between
calling VEA::Encode() on a frame and receiving it encoded via 
VEA::BitstreamBufferReady()" ?

[Justin Chuang, 2015/05/08 03:57:52]

Yes, it's in commit message. Copied over here. 

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

Thanks. Better to have it here for people reading the code in the future.

+  std::vector<base::TimeDelta> encode_latencies_;
+
   // Ids for output BitstreamBuffers.
   typedef std::map<int32, base::SharedMemory*> IdToSHM;
   ScopedVector<base::SharedMemory> output_shms_;
@@ -915,6 +932,19 @@ double VEAClient::frames_per_second() {
   return num_encoded_frames_ / duration.InSecondsF();
 }
 
+base::TimeDelta VEAClient::percentile(

[Pawel Osciak, 2015/05/07 11:31:51]

I think this doesn't have to be a member method?

[Justin Chuang, 2015/05/08 03:57:52]

It's class static private method. Shall I move to global anonymous namespace?

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

Yes please.

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

Done. BTW, I see many static functions in this file. We don't need those
'static' keyword if they are already in anonymous namespace, right?

+    const std::vector<base::TimeDelta>& sorted_values,
+    float percentage) {
+  size_t size = sorted_values.size();
+  CHECK_NE(0, size);

[Pawel Osciak, 2015/05/07 11:31:51]

CHECK_GT(size, 0) ?

[Justin Chuang, 2015/05/08 03:57:52]

Done.

+  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);

[Pawel Osciak, 2015/05/07 11:31:51]

Is this to guard ourselves from getting a percentage > 1 as an argument to this
function? Would it be more explicit to say if (percentage >= 1) return
sorted_values.back() ?

[Justin Chuang, 2015/05/08 03:57:52]

Can't change to that. It overflows even when percentage is slightly smaller than
1.0f. 

My first version is index = (size - 1) * ratio, which doesn't have overflow
issue, but is different than the official formula.

The official formula is index = max(ceil(size * ratio) - 1, 0)

The current code uses index = min(floor(size * ratio), size - 1),  which is the
same as the official formula except for marginal cases. It's still ok, I think.

Discussed with Owen, I'll change to the same as official formula to reduce
confusions for future readers.

+  return sorted_values[index];
+}
+
 void VEAClient::RequireBitstreamBuffers(unsigned int input_count,
                                         const gfx::Size& input_coded_size,
                                         size_t output_size) {
@@ -1038,7 +1068,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 +1100,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 +1130,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(frame_encode_start_ticks_.insert(
+      std::make_pair(input_id, base::TimeTicks::Now())).second);
   encoder_->Encode(video_frame, force_keyframe);
 }
 
@@ -1134,11 +1168,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();
+
+  // Record encode latency of this frame.

[Pawel Osciak, 2015/05/07 11:31:51]

We should CHECK that run_at_fps is true if we are going to measure encode
latency. Otherwise we get skewed results, since we may queue many frames at once
with the same encode start time.

[Justin Chuang, 2015/05/08 03:57:52]

You're right! This value is used in autotest only when run_at_fps is enabled.
But I cannot CHECK() it. I can only skip the related code when run_at_fps is
false. 
Please check if the next PatchSet meets your expectation (I added a helper
method to decide that).

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

Why can't we CHECK it?

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

Please see below.

+  IdToTicks::iterator it = frame_encode_start_ticks_.find(num_encoded_frames_);
+  CHECK_NE(it, frame_encode_start_ticks_.end());
+  encode_latencies_.push_back(last_frame_ready_time_ - it->second);
+  frame_encode_start_ticks_.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
@@ -1173,8 +1213,10 @@ bool VEAClient::HandleEncodedFrame(bool keyframe) {
             base::Bind(&VEAClient::OnInputTimer, base::Unretained(this)));
     }
   } else if (num_encoded_frames_ == num_frames_to_encode_) {
-    VerifyPerf();
+    LogPerf();
     VerifyStreamProperties();
+    if (test_perf_)

[Justin Chuang, 2015/05/08 03:57:52]

Added VerifyMinFPS() method

+      EXPECT_GE(frames_per_second(), kMinPerfFPS);
     SetState(CS_FINISHED);
     return false;
   }
@@ -1182,13 +1224,20 @@ 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));
-  if (test_perf_)
-    EXPECT_GE(measured_fps, kMinPerfFPS);
+                   base::StringPrintf("%.3f", frames_per_second()));
+
+  // Log encode latencies.
+  std::sort(encode_latencies_.begin(), encode_latencies_.end());
+  for (size_t i = 0; i < arraysize(kLoggedLatencyPercentages); i++) {
+    int32 percentage = kLoggedLatencyPercentages[i];

[Pawel Osciak, 2015/05/07 11:31:51]

percentiles, also, no need for int32 specifically?

[Justin Chuang, 2015/05/08 03:57:52]

Changed to p. percentile is method name.

+    base::TimeDelta latency = percentile(encode_latencies_, 0.01f * percentage);
+    g_env->LogToFile(
+        base::StringPrintf("Encode latency at %d%%", percentage),

[Owen Lin, 2015/05/07 09:53:45]

We can just use 

base::StringPrintf("Encode latency at %.0f%%", percentage * 100),

[Pawel Osciak, 2015/05/07 11:31:50]

Encode latency for %dth percentile:

[Justin Chuang, 2015/05/08 03:57:52]

Done. Added 'the' since it's full sentence.

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