vea_unittest: Calculate per-frame encode latency

content/common/gpu/media/video_encode_accelerator_unittest.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // 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"
 #include "base/files/file_util.h"
 #include "base/files/memory_mapped_file.h"
 #include "base/memory/scoped_vector.h"
 #include "base/numerics/safe_conversions.h"
 #include "base/process/process_handle.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
@@ skipping 51 matching lines @@
 // Tolerance factor for how encoded bitrate can differ from requested bitrate.
 const double kBitrateTolerance = 0.1;
 // Minimum required FPS throughput for the basic performance test.
 const uint32 kMinPerfFPS = 30;
 // Minimum (arbitrary) number of frames required to enforce bitrate requirements
 // over. Streams shorter than this may be too short to realistically require
 // an encoder to be able to converge to the requested bitrate over.
 // 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
 // The syntax of each test stream is:
 // "in_filename:width:height:out_filename:requested_bitrate:requested_framerate
 //  :requested_subsequent_bitrate:requested_subsequent_framerate"
 // - |in_filename| must be an I420 (YUV planar) raw stream
 //   (see http://www.fourcc.org/yuv.php#IYUV).
 // - |width| and |height| are in pixels.
 // - |profile| to encode into (values of media::VideoCodecProfile).
@@ skipping 475 matching lines @@
             unsigned int keyframe_period,
             bool force_bitrate,
             bool test_perf,
             bool mid_stream_bitrate_switch,
             bool mid_stream_framerate_switch,
             bool run_at_fps);
   ~VEAClient() override;
   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,
                                size_t output_buffer_size) override;
   void BitstreamBufferReady(int32 bitstream_buffer_id,
                             size_t payload_size,
                             bool key_frame) override;
   void NotifyError(VideoEncodeAccelerator::Error error) override;
 
  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();
 
   void SetState(ClientState new_state);
 
   // Set current stream parameters to given |bitrate| at |framerate|.
   void SetStreamParameters(unsigned int bitrate, unsigned int framerate);
 
   // Called when encoder is done with a VideoFrame.
@@ skipping 19 matching lines @@
   // Test codec performance, failing the test if we are currently running
   // the performance test.
   void VerifyPerf();
 
   // Write IVF file header to test_stream_->out_filename.
   void WriteIvfFileHeader();
 
   // 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|.
   void UpdateTestStreamData(bool mid_stream_bitrate_switch,
                             bool mid_stream_framerate_switch);
 
   // Callback function of the |input_timer_|.
   void OnInputTimer();
 
   ClientState state_;
   scoped_ptr<VideoEncodeAccelerator> encoder_;
 
   TestStream* test_stream_;
 
   // 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_;
   IdToSHM output_buffers_at_client_;
   int32 next_output_buffer_id_;
 
   // Current offset into input stream.
   off_t pos_in_input_stream_;
   gfx::Size input_coded_size_;
   // Requested by encoder.
@@ skipping 248 matching lines @@
   }
   if (requested_subsequent_framerate_ == 0)
     requested_subsequent_framerate_ = 1;
 }
 
 double VEAClient::frames_per_second() {
   base::TimeDelta duration = last_frame_ready_time_ - encode_start_time_;
   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) {
   DCHECK(thread_checker_.CalledOnValidThread());
   ASSERT_EQ(state_, CS_INITIALIZED);
   SetState(CS_ENCODING);
 
   CreateAlignedInputStreamFile(input_coded_size, test_stream_);
 
   num_frames_to_encode_ = test_stream_->num_frames;
@@ skipping 103 matching lines @@
 }
 
 void VEAClient::InputNoLongerNeededCallback(int32 input_id) {
   std::set<int32>::iterator it = inputs_at_client_.find(input_id);
   ASSERT_NE(it, inputs_at_client_.end());
   inputs_at_client_.erase(it);
   if (!run_at_fps_)
     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());
 
   uint8* frame_data_y = const_cast<uint8*>(
       test_stream_->mapped_aligned_in_file.data() + position);
   uint8* frame_data_u = frame_data_y + test_stream_->aligned_plane_size[0];
   uint8* frame_data_v = frame_data_u + test_stream_->aligned_plane_size[1];
 
   CHECK_GT(current_framerate_, 0U);
   scoped_refptr<media::VideoFrame> frame =
@@ skipping 10 matching lines @@
           frame_data_v,
           base::TimeDelta().FromMilliseconds(
               next_input_id_ * base::Time::kMillisecondsPerSecond /
               current_framerate_),
           media::BindToCurrentLoop(
               base::Bind(&VEAClient::InputNoLongerNeededCallback,
                          base::Unretained(this),
                          next_input_id_)));
 
   CHECK(inputs_at_client_.insert(next_input_id_).second);
-  ++next_input_id_;
 
+  *input_id = next_input_id_++;
   return frame;
 }
 
 void VEAClient::OnInputTimer() {
   if (!has_encoder() || state_ != CS_ENCODING)
     input_timer_.reset();
   else if (inputs_at_client_.size() <
            num_required_input_buffers_ + kNumExtraInputFrames)
     FeedEncoderWithOneInput();
   else
     DVLOG(1) << "Dropping input frame";
 }
 
 void VEAClient::FeedEncoderWithOneInput() {
   if (!has_encoder() || state_ != CS_ENCODING)
     return;
 
   size_t bytes_left =
       test_stream_->mapped_aligned_in_file.length() - pos_in_input_stream_;
   if (bytes_left < test_stream_->aligned_buffer_size) {
     DCHECK_EQ(bytes_left, 0UL);
     // Rewind if at the end of stream and we are still encoding.
     // This is to flush the encoder with additional frames from the beginning
     // of the stream, or if the stream is shorter that the number of frames
     // we require for bitrate tests.
     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);
 }
 
 void VEAClient::FeedEncoderWithOutput(base::SharedMemory* shm) {
   if (!has_encoder())
     return;
 
   if (state_ != CS_ENCODING)
     return;
 
   base::SharedMemoryHandle dup_handle;
   CHECK(shm->ShareToProcess(base::GetCurrentProcessHandle(), &dup_handle));
 
   media::BitstreamBuffer bitstream_buffer(
       next_output_buffer_id_++, dup_handle, output_buffer_size_);
   CHECK(output_buffers_at_client_.insert(std::make_pair(bitstream_buffer.id(),
                                                         shm)).second);
   encoder_->UseOutputBitstreamBuffer(bitstream_buffer);
 }
 
 bool VEAClient::HandleEncodedFrame(bool keyframe) {
   // This would be a bug in the test, which should not ignore false
   // 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
   // before the one we requested it for (if the keyframe request
   // is asynchronous, i.e. not bound to any concrete frame, and because
   // the pipeline can be deeper than one frame), at that frame, or after.
   // So the only constraints we put here is that we get a keyframe not
   // earlier than we requested one (in time), and not later than
   // kMaxKeyframeDelay frames after the frame, for which we requested
   // it, comes back encoded.
@@ skipping 23 matching lines @@
   } else if (num_encoded_frames_ == num_frames_to_encode_) {
     VerifyPerf();
     VerifyStreamProperties();
     SetState(CS_FINISHED);
     return false;
   }
 
   return true;
 }
 
 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() {
   CHECK_GT(num_frames_since_last_check_, 0UL);
   CHECK_GT(encoded_stream_size_since_last_check_, 0UL);
   unsigned int bitrate = encoded_stream_size_since_last_check_ * 8 *
                          current_framerate_ / num_frames_since_last_check_;
   DVLOG(1) << "Current chunk's bitrate: " << bitrate
            << " (expected: " << current_requested_bitrate_
            << " @ " << current_framerate_ << " FPS,"
@@ skipping 239 matching lines @@
   }
 
   content::g_env =
       reinterpret_cast<content::VideoEncodeAcceleratorTestEnvironment*>(
           testing::AddGlobalTestEnvironment(
               new content::VideoEncodeAcceleratorTestEnvironment(
                   test_stream_data.Pass(), log_path, run_at_fps)));
 
   return RUN_ALL_TESTS();
 }