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 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
 // 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 292 matching lines @@
     ParseAndReadTestStreamData(*test_stream_data_, &test_streams_);
   }
 
   virtual void TearDown() {
     for (size_t i = 0; i < test_streams_.size(); i++) {
       base::DeleteFile(test_streams_[i]->aligned_in_file, false);
     }
     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());
     }
   }
 
   ScopedVector<TestStream> test_streams_;
   bool run_at_fps_;
 
  private:
   scoped_ptr<base::FilePath::StringType> test_stream_data_;
   base::FilePath log_path_;
@@ skipping 157 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(); }
 
+  // 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();
 
   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.
   void InputNoLongerNeededCallback(int32 input_id);
 
   // Feed the encoder with one input frame.
   void FeedEncoderWithOneInput();
 
   // Provide the encoder with a new output buffer.
   void FeedEncoderWithOutput(base::SharedMemory* shm);
 
   // Called on finding a complete frame (with |keyframe| set to true for
   // keyframes) in the stream, to perform codec-independent, per-frame checks
   // 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();
 
   // 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_;
 
+  // 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_;
   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 36 matching lines @@
 
   // Byte size of the encoded stream (for bitrate calculation) since last
   // time we checked bitrate.
   size_t encoded_stream_size_since_last_check_;
 
   // If true, verify performance at the end of the test.
   bool test_perf_;
 
   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_;
 
   // All methods of this class should be run on the same thread.
   base::ThreadChecker thread_checker_;
 
   // Requested bitrate in bits per second.
   unsigned int requested_bitrate_;
 
   // Requested initial framerate.
@@ skipping 185 matching lines @@
       requested_subsequent_framerate_ =
           test_stream_->requested_subsequent_framerate;
   } else {
     requested_subsequent_framerate_ = requested_framerate_;
   }
   if (requested_subsequent_framerate_ == 0)
     requested_subsequent_framerate_ = 1;
 }
 
 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) {
   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;
   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) {
     DVLOG(1) << "Stream too short for bitrate test ("
              << test_stream_->num_frames << " frames), will loop it to reach "
              << kMinFramesForBitrateTests << " frames";
     num_frames_to_encode_ = kMinFramesForBitrateTests;
   }
   if (save_to_file_ && IsVP8(test_stream_->requested_profile))
     WriteIvfFileHeader();
 
   input_coded_size_ = input_coded_size;
   num_required_input_buffers_ = input_count;
   ASSERT_GT(num_required_input_buffers_, 0UL);
 
   output_buffer_size_ = output_size;
   ASSERT_GT(output_buffer_size_, 0UL);
 
   for (unsigned int i = 0; i < kNumOutputBuffers; ++i) {
     base::SharedMemory* shm = new base::SharedMemory();
     CHECK(shm->CreateAndMapAnonymous(output_buffer_size_));
     output_shms_.push_back(shm);
     FeedEncoderWithOutput(shm);
   }
 
-  encode_start_time_ = base::TimeTicks::Now();
   if (run_at_fps_) {
     input_timer_.reset(new base::RepeatingTimer<VEAClient>());
     input_timer_->Start(
         FROM_HERE, base::TimeDelta::FromSeconds(1) / current_framerate_,
         base::Bind(&VEAClient::OnInputTimer, base::Unretained(this)));
   } else {
     while (inputs_at_client_.size() <
            num_required_input_buffers_ + kNumExtraInputFrames)
       FeedEncoderWithOneInput();
   }
@@ skipping 64 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_EQ(input_id, static_cast<int32>(encode_start_time_.size()));
+  encode_start_time_.push_back(base::TimeTicks::Now());
   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();
+
+  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
   // 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 14 matching lines @@
     if (requested_subsequent_bitrate_ != current_requested_bitrate_ ||
         requested_subsequent_framerate_ != current_framerate_) {
       SetStreamParameters(requested_subsequent_bitrate_,
                           requested_subsequent_framerate_);
       if (run_at_fps_ && input_timer_)
         input_timer_->Start(
             FROM_HERE, base::TimeDelta::FromSeconds(1) / current_framerate_,
             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;
   }
 
   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() {
   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();
 }