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 <inttypes.h>
+
+#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 48 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.
+const unsigned int 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 100 matching lines @@
     int bytes = file->Write(offset + written_bytes,
                             reinterpret_cast<const char*>(data + written_bytes),
                             size - written_bytes);
     if (bytes <= 0)
       return false;
     written_bytes += bytes;
   }
   return true;
 }
 
+// Return the |percentile| from a sorted vector.
+static base::TimeDelta Percentile(
+    const std::vector<base::TimeDelta>& sorted_values,
+    unsigned int percentile) {
+  size_t size = sorted_values.size();
+  CHECK_GT(size, 0UL);
+  CHECK_LE(percentile, 100);

[achuithb, 2015/05/15 00:24:10]

It's pretty sad, but the compiler seems to think 100 is a signed int here.

+  // Use Nearest Rank method in http://en.wikipedia.org/wiki/Percentile.
+  int index =
+      std::max(static_cast<int>(ceil(0.01f * percentile * size)) - 1, 0);
+  return sorted_values[index];
+}
+
 static bool IsH264(media::VideoCodecProfile profile) {
   return profile >= media::H264PROFILE_MIN && profile <= media::H264PROFILE_MAX;
 }
 
 static bool IsVP8(media::VideoCodecProfile profile) {
   return profile >= media::VP8PROFILE_MIN && profile <= media::VP8PROFILE_MAX;
 }
 
 // ARM performs CPU cache management with CPU cache line granularity. We thus
 // need to ensure our buffers are CPU cache line-aligned (64 byte-aligned).
@@ skipping 151 matching lines @@
 // setup it once for all test cases.
 // It helps
 // - maintain test stream data and other test settings.
 // - clean up temporary aligned files.
 // - output log to file.
 class VideoEncodeAcceleratorTestEnvironment : public ::testing::Environment {
  public:
   VideoEncodeAcceleratorTestEnvironment(
       scoped_ptr<base::FilePath::StringType> data,
       const base::FilePath& log_path,
-      bool run_at_fps)
-      : run_at_fps_(run_at_fps),
-        test_stream_data_(data.Pass()),
-        log_path_(log_path) {}
+      bool run_at_fps,
+      bool needs_encode_latency)
+      : test_stream_data_(data.Pass()),
+        log_path_(log_path),
+        run_at_fps_(run_at_fps),
+        needs_encode_latency_(needs_encode_latency) {}
 
   virtual void SetUp() {
     if (!log_path_.empty()) {
       log_file_.reset(new base::File(
           log_path_, base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE));
       CHECK(log_file_->IsValid());
     }
     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 video_VEAPerf autotest parses the output key and value
+  // pairs. Be 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;
     if (log_file_) {
-      std::string s =
-          base::StringPrintf("%s: %s\n", key.c_str(), value.c_str());
       log_file_->WriteAtCurrentPos(s.data(), s.length());
     }
   }
 
+  // Feed the encoder with the input buffers at the requested framerate. If
+  // false, feed as fast as possible. This is set by the command line switch
+  // "--run_at_fps".
+  bool run_at_fps() const { return run_at_fps_; }
+
+  // Whether to measure encode latency. This is set by the command line switch
+  // "--measure_latency".
+  bool needs_encode_latency() const { return needs_encode_latency_; }
+
   ScopedVector<TestStream> test_streams_;
-  bool run_at_fps_;
 
  private:
   scoped_ptr<base::FilePath::StringType> test_stream_data_;
   base::FilePath log_path_;
   scoped_ptr<base::File> log_file_;
+  bool run_at_fps_;
+  bool needs_encode_latency_;
 };
 
 enum ClientState {
   CS_CREATED,
   CS_ENCODER_SET,
   CS_INITIALIZED,
   CS_ENCODING,
   CS_FINISHED,
   CS_ERROR,
 };
@@ skipping 140 matching lines @@
 
 class VEAClient : public VideoEncodeAccelerator::Client {
  public:
   VEAClient(TestStream* test_stream,
             ClientStateNotification<ClientState>* note,
             bool save_to_file,
             unsigned int keyframe_period,
             bool force_bitrate,
             bool test_perf,
             bool mid_stream_bitrate_switch,
-            bool mid_stream_framerate_switch,
-            bool run_at_fps);
+            bool mid_stream_framerate_switch);
   ~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();
+
   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 position in the vector is the
+  // frame input id.
+  std::vector<base::TimeTicks> encode_start_time_;
+  // The encode latencies of all encoded frames. We define encode latency as the
+  // 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.
   unsigned int requested_framerate_;
 
   // Bitrate to switch to in the middle of the stream.
   unsigned int requested_subsequent_bitrate_;
 
   // Framerate to switch to in the middle of the stream.
   unsigned int requested_subsequent_framerate_;
 
   // The timer used to feed the encoder with the input frames.
   scoped_ptr<base::RepeatingTimer<VEAClient>> input_timer_;
-
-  // Feed the encoder with the input buffers at the |requested_framerate_|. If
-  // false, feed as fast as possible. This is set by the command line switch
-  // "--run_at_fps".
-  bool run_at_fps_;
 };
 
 VEAClient::VEAClient(TestStream* test_stream,
                      ClientStateNotification<ClientState>* note,
                      bool save_to_file,
                      unsigned int keyframe_period,
                      bool force_bitrate,
                      bool test_perf,
                      bool mid_stream_bitrate_switch,
-                     bool mid_stream_framerate_switch,
-                     bool run_at_fps)
+                     bool mid_stream_framerate_switch)
     : state_(CS_CREATED),
       test_stream_(test_stream),
       note_(note),
       next_input_id_(0),
       next_output_buffer_id_(0),
       pos_in_input_stream_(0),
       num_required_input_buffers_(0),
       output_buffer_size_(0),
       num_frames_to_encode_(0),
       num_encoded_frames_(0),
       num_frames_since_last_check_(0),
       seen_keyframe_in_this_buffer_(false),
       save_to_file_(save_to_file),
       keyframe_period_(keyframe_period),
       num_keyframes_requested_(0),
       next_keyframe_at_(0),
       force_bitrate_(force_bitrate),
       current_requested_bitrate_(0),
       current_framerate_(0),
       encoded_stream_size_since_last_check_(0),
       test_perf_(test_perf),
       requested_bitrate_(0),
       requested_framerate_(0),
       requested_subsequent_bitrate_(0),
-      requested_subsequent_framerate_(0),
-      run_at_fps_(run_at_fps) {
+      requested_subsequent_framerate_(0) {
   if (keyframe_period_)
     CHECK_LT(kMaxKeyframeDelay, keyframe_period_);
 
   // Fake encoder produces an invalid stream, so skip validating it.
   if (!g_fake_encoder) {
     validator_ = StreamValidator::Create(
         test_stream_->requested_profile,
         base::Bind(&VEAClient::HandleEncodedFrame, base::Unretained(this)));
     CHECK(validator_);
   }
@@ skipping 123 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_;
+  CHECK(!encode_start_time_.empty());
+  base::TimeDelta duration = last_frame_ready_time_ - encode_start_time_[0];
   return num_encoded_frames_ / duration.InSecondsF();
 }
 
 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;
 
+  // Speed up vector insertion.
+  encode_start_time_.reserve(num_frames_to_encode_);
+  if (g_env->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_) {
+  if (g_env->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 59 matching lines @@
   encoder_->RequestEncodingParametersChange(current_requested_bitrate_,
                                             current_framerate_);
   DVLOG(1) << "Switched parameters to " << current_requested_bitrate_
            << " bps @ " << current_framerate_ << " FPS";
 }
 
 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_)
+  if (!g_env->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 (g_env->needs_encode_latency()) {
+    CHECK_LT(num_encoded_frames_, encode_start_time_.size());
+    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);
+  }
+
   ++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.
   if (keyframe) {
     if (num_keyframes_requested_ > 0 &&
         num_encoded_frames_ > next_keyframe_at_) {
       --num_keyframes_requested_;
       next_keyframe_at_ += keyframe_period_;
     }
     seen_keyframe_in_this_buffer_ = true;
   }
 
   if (num_keyframes_requested_ > 0)
     EXPECT_LE(num_encoded_frames_, next_keyframe_at_ + kMaxKeyframeDelay);
 
   if (num_encoded_frames_ == num_frames_to_encode_ / 2) {
     VerifyStreamProperties();
     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_)
+      if (g_env->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() {
   g_env->LogToFile("Measured encoder FPS",
-                   base::StringPrintf("%.3f", measured_fps));
+                   base::StringPrintf("%.3f", frames_per_second()));
+
+  // Log encode latencies.
+  if (g_env->needs_encode_latency()) {
+    std::sort(encode_latencies_.begin(), encode_latencies_.end());
+    for (const auto& percentile : kLoggedLatencyPercentiles) {
+      base::TimeDelta latency = Percentile(encode_latencies_, percentile);
+      g_env->LogToFile(
+          base::StringPrintf("Encode latency for the %dth percentile",
+                             percentile),
+          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 86 matching lines @@
 
   // Create all encoders.
   for (size_t i = 0; i < num_concurrent_encoders; i++) {
     size_t test_stream_index = i % g_env->test_streams_.size();
     // Disregard save_to_file if we didn't get an output filename.
     bool encoder_save_to_file =
         (save_to_file &&
          !g_env->test_streams_[test_stream_index]->out_filename.empty());
 
     notes.push_back(new ClientStateNotification<ClientState>());
-    clients.push_back(
-        new VEAClient(g_env->test_streams_[test_stream_index], notes.back(),
-                      encoder_save_to_file, keyframe_period, force_bitrate,
-                      test_perf, mid_stream_bitrate_switch,
-                      mid_stream_framerate_switch, g_env->run_at_fps_));
+    clients.push_back(new VEAClient(
+        g_env->test_streams_[test_stream_index], notes.back(),
+        encoder_save_to_file, keyframe_period, force_bitrate, test_perf,
+        mid_stream_bitrate_switch, mid_stream_framerate_switch));
 
     encoder_thread.message_loop()->PostTask(
         FROM_HERE,
         base::Bind(&VEAClient::CreateEncoder,
                    base::Unretained(clients.back())));
   }
 
   // All encoders must pass through states in this order.
   enum ClientState state_transitions[] = {CS_ENCODER_SET, CS_INITIALIZED,
                                           CS_ENCODING, CS_FINISHED};
@@ skipping 79 matching lines @@
 
   // Needed to enable DVLOG through --vmodule.
   logging::LoggingSettings settings;
   settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
   CHECK(logging::InitLogging(settings));
 
   const base::CommandLine* cmd_line = base::CommandLine::ForCurrentProcess();
   DCHECK(cmd_line);
 
   bool run_at_fps = false;
+  bool needs_encode_latency = false;
   base::FilePath log_path;
 
   base::CommandLine::SwitchMap switches = cmd_line->GetSwitches();
   for (base::CommandLine::SwitchMap::const_iterator it = switches.begin();
        it != switches.end();
        ++it) {
     if (it->first == "test_stream_data") {
       test_stream_data->assign(it->second.c_str());
       continue;
     }
     // Output machine-readable logs with fixed formats to a file.
     if (it->first == "output_log") {
       log_path = base::FilePath(
           base::FilePath::StringType(it->second.begin(), it->second.end()));
       continue;
     }
     if (it->first == "num_frames_to_encode") {
       std::string input(it->second.begin(), it->second.end());
       CHECK(base::StringToInt(input, &content::g_num_frames_to_encode));
       continue;
     }
+    if (it->first == "measure_latency") {
+      needs_encode_latency = true;
+      continue;
+    }
     if (it->first == "fake_encoder") {
       content::g_fake_encoder = true;
       continue;
     }
     if (it->first == "run_at_fps") {
       run_at_fps = true;
       continue;
     }
     if (it->first == "v" || it->first == "vmodule")
       continue;
     if (it->first == "ozone-platform" || it->first == "ozone-use-surfaceless")
       continue;
     LOG(FATAL) << "Unexpected switch: " << it->first << ":" << it->second;
   }
 
+  if (needs_encode_latency && !run_at_fps) {
+    // 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.
+    LOG(FATAL) << "--measure_latency requires --run_at_fps enabled to work.";
+  }
+
 #if defined(OS_CHROMEOS) && defined(ARCH_CPU_X86_FAMILY)
   content::VaapiWrapper::PreSandboxInitialization();
 #endif
 
   content::g_env =
       reinterpret_cast<content::VideoEncodeAcceleratorTestEnvironment*>(
           testing::AddGlobalTestEnvironment(
               new content::VideoEncodeAcceleratorTestEnvironment(
-                  test_stream_data.Pass(), log_path, run_at_fps)));
+                  test_stream_data.Pass(), log_path, run_at_fps,
+                  needs_encode_latency)));
 
   return RUN_ALL_TESTS();
 }