Adding cpu measurments to video_quality_tests

webrtc/video/video_quality_test.cc

 /*
  *  Copyright (c) 2015 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 #include "webrtc/video/video_quality_test.h"
 
 #include <stdio.h>
 #include <algorithm>
 #include <deque>
 #include <map>
 #include <sstream>
 #include <string>
 #include <vector>
 
 #include "webrtc/base/checks.h"
+#include "webrtc/base/cpu_time.h"
 #include "webrtc/base/event.h"
 #include "webrtc/base/format_macros.h"
 #include "webrtc/base/optional.h"
 #include "webrtc/base/platform_file.h"
 #include "webrtc/base/timeutils.h"
 #include "webrtc/call/call.h"
 #include "webrtc/common_video/libyuv/include/webrtc_libyuv.h"
 #include "webrtc/logging/rtc_event_log/rtc_event_log.h"
 #include "webrtc/modules/audio_mixer/audio_mixer_impl.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_header_parser.h"
@@ skipping 124 matching lines @@
         pre_encode_proxy_(this),
         encode_timing_proxy_(this),
         frames_to_process_(duration_frames),
         frames_recorded_(0),
         frames_processed_(0),
         dropped_frames_(0),
         dropped_frames_before_first_encode_(0),
         dropped_frames_before_rendering_(0),
         last_render_time_(0),
         rtp_timestamp_delta_(0),
+        cpu_time_(0),
+        wallclock_time_(0),
         avg_psnr_threshold_(avg_psnr_threshold),
         avg_ssim_threshold_(avg_ssim_threshold),
         is_quick_test_enabled_(is_quick_test_enabled),
         stats_polling_thread_(&PollStatsThread, this, "StatsPoller"),
         comparison_available_event_(false, false),
         done_(true, false) {
     // Create thread pool for CPU-expensive PSNR/SSIM calculations.
 
     // Try to use about as many threads as cores, but leave kMinCoresLeft alone,
     // so that we don't accidentally starve "real" worker threads (codec etc).
@@ skipping 11 matching lines @@
       num_cores -= kMinCoresLeft;
       num_cores = std::min(num_cores, kMaxComparisonThreads);
     }
 
     for (uint32_t i = 0; i < num_cores; ++i) {
       rtc::PlatformThread* thread =
           new rtc::PlatformThread(&FrameComparisonThread, this, "Analyzer");
       thread->Start();
       comparison_thread_pool_.push_back(thread);
     }
+
+    // Start time measurements

[sprang_webrtc, 2017/02/21 15:43:20]

nit: End comments with period.

[ilnik, 2017/02/22 08:43:28]

Done.

+    cpu_time_ -= rtc::GetProcessCpuTimeNanos();

[sprang_webrtc, 2017/02/21 15:43:20]

I was a bit confused of the usage here at first. Can you maybe rename them
cpu_time_start_offset_ or something and don't start the negative offset. Then
just take the delta in a local variable at the end?

[sprang_webrtc, 2017/02/21 15:43:20]

I'm not sure we should start measuring time from the construction time of the
analyzer. Then we'll include some setup time, may include open files for the
capturer etc. 

Maybe you can set the start time in Wait()? Possibly add an explicit Start()
method, might be other things that should go there as well.

[ilnik, 2017/02/22 08:43:28]

Done.

[ilnik, 2017/02/22 08:43:28]

I created special functions for manipulating cpu_time_. I hope now it's clear
that's happening there.

+    wallclock_time_ -= rtc::SystemTimeNanos();
   }
 
   ~VideoAnalyzer() {
     for (rtc::PlatformThread* thread : comparison_thread_pool_) {
       thread->Stop();
       delete thread;
     }
   }
 
   virtual void SetReceiver(PacketReceiver* receiver) { receiver_ = receiver; }
@@ skipping 117 matching lines @@
     rtc::CritScope lock(&comparison_lock_);
     if (frames_recorded_ < frames_to_process_)
       encoded_frame_size_.AddSample(frame.length_);
   }
 
   void OnFrame(const VideoFrame& video_frame) override {
     int64_t render_time_ms =
         Clock::GetRealTimeClock()->CurrentNtpInMilliseconds();
 
     rtc::CritScope lock(&crit_);
+
+    cpu_time_ += rtc::GetThreadCpuTimeNanos();

[sprang_webrtc, 2017/02/21 15:43:20]

Is this scope significant?
I think it would be more readable if you create a temp variable here. Maybe
int64_t comparison_cpu_time_start_offset_ = rtc::GetThreadCpuTimeNanos();

[ilnik, 2017/02/22 08:43:28]

Done it the other way.

+
     int64_t send_timestamp =
         wrap_handler_.Unwrap(video_frame.timestamp() - rtp_timestamp_delta_);
 
     while (wrap_handler_.Unwrap(frames_.front().timestamp()) < send_timestamp) {
       if (!last_rendered_frame_) {
         // No previous frame rendered, this one was dropped after sending but
         // before rendering.
         ++dropped_frames_before_rendering_;
       } else {
         AddFrameComparison(frames_.front(), *last_rendered_frame_, true,
@@ skipping 10 matching lines @@
     if (send_timestamp == reference_timestamp - 1) {
       // TODO(ivica): Make this work for > 2 streams.
       // Look at RTPSender::BuildRTPHeader.
       ++send_timestamp;
     }
     ASSERT_EQ(reference_timestamp, send_timestamp);
 
     AddFrameComparison(reference_frame, video_frame, false, render_time_ms);
 
     last_rendered_frame_ = rtc::Optional<VideoFrame>(video_frame);
+
+    cpu_time_ -= rtc::GetThreadCpuTimeNanos();

[sprang_webrtc, 2017/02/21 15:43:20]

...and here did something like
cpu_time_start_offset_ += rtc::GetThreadCpuTimeNanos() -
comparison_cpu_time_start_offset_;

[ilnik, 2017/02/22 08:43:28]

Acknowledged.

   }
 
   void Wait() {
     // Frame comparisons can be very expensive. Wait for test to be done, but
     // at time-out check if frames_processed is going up. If so, give it more
     // time, otherwise fail. Hopefully this will reduce test flakiness.
 
     stats_polling_thread_.Start();
 
     int last_frames_processed = -1;
@@ skipping 229 matching lines @@
       // Wait until new comparison task is available, or test is done.
       // If done, wake up remaining threads waiting.
       comparison_available_event_.Wait(1000);
       if (AllFramesRecorded()) {
         comparison_available_event_.Set();
         return false;
       }
       return true;  // Try again.
     }
 
+    {
+      rtc::CritScope crit(&comparison_lock_);
+      cpu_time_ += rtc::GetThreadCpuTimeNanos();

[sprang_webrtc, 2017/02/21 15:43:20]

Could do same thing with a local temp timestamp here as above.

[ilnik, 2017/02/22 08:43:28]

Acknowledged.

+    }
+
     PerformFrameComparison(comparison);
 
+    {
+      rtc::CritScope crit(&comparison_lock_);
+      cpu_time_ -= rtc::GetThreadCpuTimeNanos();
+    }
+
     if (FrameProcessed()) {
       PrintResults();
       if (graph_data_output_file_)
         PrintSamplesToFile();
       done_.Set();
       comparison_available_event_.Set();
       return false;
     }
 
     return true;
@@ skipping 33 matching lines @@
   // last frame to be processed.
   bool FrameProcessed() {
     rtc::CritScope crit(&comparison_lock_);
     ++frames_processed_;
     assert(frames_processed_ <= frames_to_process_);
     return frames_processed_ == frames_to_process_;
   }
 
   void PrintResults() {
     rtc::CritScope crit(&comparison_lock_);
+    cpu_time_ += rtc::GetProcessCpuTimeNanos();
+    wallclock_time_ += rtc::SystemTimeNanos();
+
     PrintResult("psnr", psnr_, " dB");
     PrintResult("ssim", ssim_, " score");
     PrintResult("sender_time", sender_time_, " ms");
     PrintResult("receiver_time", receiver_time_, " ms");
     PrintResult("total_delay_incl_network", end_to_end_, " ms");
     PrintResult("time_between_rendered_frames", rendered_delta_, " ms");
     PrintResult("encoded_frame_size", encoded_frame_size_, " bytes");
     PrintResult("encode_frame_rate", encode_frame_rate_, " fps");
     PrintResult("encode_time", encode_time_ms_, " ms");
     PrintResult("encode_usage_percent", encode_usage_percent_, " percent");
     PrintResult("media_bitrate", media_bitrate_bps_, " bps");
 
     if (receive_stream_ != nullptr) {
       PrintResult("decode_time", decode_time_ms_, " ms");
       PrintResult("decode_time_max", decode_time_max_ms_, " ms");
     }
 
     printf("RESULT dropped_frames: %s = %d frames\n", test_label_.c_str(),
            dropped_frames_);
     printf("RESULT dropped_frames_before_first_encode: %s = %d frames\n",
            test_label_.c_str(), dropped_frames_before_first_encode_);
     printf("RESULT dropped_frames_before_rendering: %s = %d frames\n",
            test_label_.c_str(), dropped_frames_before_rendering_);
+    printf("RESULT cpu_usage: %s = %lf %%\n", test_label_.c_str(),
+           static_cast<double>(cpu_time_) / wallclock_time_ * 100.0);
     //  Disable quality check for quick test, as quality checks may fail
     //  because too few samples were collected.
     if (!is_quick_test_enabled_) {
       EXPECT_GT(psnr_.Mean(), avg_psnr_threshold_);
       EXPECT_GT(ssim_.Mean(), avg_ssim_threshold_);
     }
   }
 
   void PerformFrameComparison(const FrameComparison& comparison) {
     // Perform expensive psnr and ssim calculations while not holding lock.
@@ skipping 178 matching lines @@
   test::Statistics media_bitrate_bps_ GUARDED_BY(comparison_lock_);
 
   const int frames_to_process_;
   int frames_recorded_;
   int frames_processed_;
   int dropped_frames_;
   int dropped_frames_before_first_encode_;
   int dropped_frames_before_rendering_;
   int64_t last_render_time_;
   uint32_t rtp_timestamp_delta_;
+  int64_t cpu_time_;
+  int64_t wallclock_time_;
 
   rtc::CriticalSection crit_;
   std::deque<VideoFrame> frames_ GUARDED_BY(crit_);
   rtc::Optional<VideoFrame> last_rendered_frame_ GUARDED_BY(crit_);
   rtc::TimestampWrapAroundHandler wrap_handler_ GUARDED_BY(crit_);
   std::map<int64_t, int64_t> send_times_ GUARDED_BY(crit_);
   std::map<int64_t, int64_t> recv_times_ GUARDED_BY(crit_);
   std::map<int64_t, size_t> encoded_frame_sizes_ GUARDED_BY(crit_);
   rtc::Optional<uint32_t> first_encoded_timestamp_ GUARDED_BY(crit_);
   rtc::Optional<uint32_t> first_sent_timestamp_ GUARDED_BY(crit_);
@@ skipping 706 matching lines @@
     std::ostringstream str;
     str << receive_logs_++;
     std::string path =
         params_.video.encoded_frame_base_path + "." + str.str() + ".recv.ivf";
     stream->EnableEncodedFrameRecording(rtc::CreatePlatformFile(path),
                                         10000000);
   }
 }
 
 }  // namespace webrtc