Add performance tracing for PlatformThread and parts of the video code.

webrtc/modules/video_coding/frame_buffer2.cc

 /*
  *  Copyright (c) 2016 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/modules/video_coding/frame_buffer2.h"
 
 #include <algorithm>
 #include <cstring>
 #include <queue>
 
 #include "webrtc/base/checks.h"
 #include "webrtc/base/logging.h"
+#include "webrtc/base/trace_event.h"
 #include "webrtc/modules/video_coding/include/video_coding_defines.h"
 #include "webrtc/modules/video_coding/jitter_estimator.h"
 #include "webrtc/modules/video_coding/timing.h"
 #include "webrtc/system_wrappers/include/clock.h"
 #include "webrtc/system_wrappers/include/metrics.h"
 
 namespace webrtc {
 namespace video_coding {
 
 namespace {
@@ skipping 19 matching lines @@
       num_frames_buffered_(0),
       stopped_(false),
       protection_mode_(kProtectionNack),
       stats_callback_(stats_callback) {}
 
 FrameBuffer::~FrameBuffer() {}
 
 FrameBuffer::ReturnReason FrameBuffer::NextFrame(
     int64_t max_wait_time_ms,
     std::unique_ptr<FrameObject>* frame_out) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::NextFrame");

[philipel, 2017/03/03 12:08:34]

If tracing is done in interest of profiling performance then this trace wont
make much sense. Also, not sure if it matters, but this function is recursive
(line 152). :)

[tommi, 2017/03/03 13:07:58]

Both wall clock time and cpu time are useful when profiling.  As is, depending
on the scenario, the thread can spend little or a lot of time sleeping, which is
useful information.  If you use chrome://tracing to look at the data, you'll see
for example that if you have 10 incoming streams, there will be 10 threads, all
of which will be sleeping (on my machine) about 27ms in this function, or close
to 1/10th of a frame, then waking up to decode a frame.

For the purposes of this entry, it doesn't matter if it's recursive, but it will
show up in the trace data when we hit that code path, which can be useful.

   int64_t latest_return_time_ms =
       clock_->TimeInMilliseconds() + max_wait_time_ms;
   int64_t wait_ms = max_wait_time_ms;
 
   do {
     int64_t now_ms = clock_->TimeInMilliseconds();
     {
       rtc::CritScope lock(&crit_);
       new_countinuous_frame_event_.Reset();
       if (stopped_)
@@ skipping 79 matching lines @@
     // means that the frame buffer was cleared as the thread in this function
     // was waiting to acquire |crit_| in order to return. Wait for the
     // remaining time and then return.
     return NextFrame(latest_return_time_ms - now_ms, frame_out);
   } else {
     return kTimeout;
   }
 }
 
 void FrameBuffer::SetProtectionMode(VCMVideoProtection mode) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::SetProtectionMode");
   rtc::CritScope lock(&crit_);
   protection_mode_ = mode;
 }
 
 void FrameBuffer::Start() {
+  TRACE_EVENT0("webrtc", "FrameBuffer::Start");
   rtc::CritScope lock(&crit_);
   stopped_ = false;
 }
 
 void FrameBuffer::Stop() {
+  TRACE_EVENT0("webrtc", "FrameBuffer::Stop");
   rtc::CritScope lock(&crit_);
   stopped_ = true;
   new_countinuous_frame_event_.Set();
 }
 
 int FrameBuffer::InsertFrame(std::unique_ptr<FrameObject> frame) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::InsertFrame");
   rtc::CritScope lock(&crit_);
   RTC_DCHECK(frame);
 
   if (stats_callback_)
     stats_callback_->OnCompleteFrame(frame->num_references == 0, frame->size());
 
   FrameKey key(frame->picture_id, frame->spatial_layer);
   int last_continuous_picture_id =
       last_continuous_frame_it_ == frames_.end()
           ? -1
@@ skipping 62 matching lines @@
     // Since we now have new continuous frames there might be a better frame
     // to return from NextFrame. Signal that thread so that it again can choose
     // which frame to return.
     new_countinuous_frame_event_.Set();
   }
 
   return last_continuous_picture_id;
 }
 
 void FrameBuffer::PropagateContinuity(FrameMap::iterator start) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::PropagateContinuity");
   RTC_DCHECK(start->second.continuous);
   if (last_continuous_frame_it_ == frames_.end())
     last_continuous_frame_it_ = start;
 
   std::queue<FrameMap::iterator> continuous_frames;
   continuous_frames.push(start);
 
   // A simple BFS to traverse continuous frames.
   while (!continuous_frames.empty()) {
     auto frame = continuous_frames.front();
@@ skipping 10 matching lines @@
 
       if (frame_ref->second.num_missing_continuous == 0) {
         frame_ref->second.continuous = true;
         continuous_frames.push(frame_ref);
       }
     }
   }
 }
 
 void FrameBuffer::PropagateDecodability(const FrameInfo& info) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::PropagateDecodability");
   for (size_t d = 0; d < info.num_dependent_frames; ++d) {
     auto ref_info = frames_.find(info.dependent_frames[d]);
     RTC_DCHECK(ref_info != frames_.end());
     RTC_DCHECK_GT(ref_info->second.num_missing_decodable, 0U);
     --ref_info->second.num_missing_decodable;
   }
 }
 
 void FrameBuffer::AdvanceLastDecodedFrame(FrameMap::iterator decoded) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::AdvanceLastDecodedFrame");
   if (last_decoded_frame_it_ == frames_.end()) {
     last_decoded_frame_it_ = frames_.begin();
   } else {
     RTC_DCHECK(last_decoded_frame_it_->first < decoded->first);
     ++last_decoded_frame_it_;
   }
   --num_frames_buffered_;
   ++num_frames_history_;
 
   // First, delete non-decoded frames from the history.
   while (last_decoded_frame_it_ != decoded) {
     if (last_decoded_frame_it_->second.frame)
       --num_frames_buffered_;
     last_decoded_frame_it_ = frames_.erase(last_decoded_frame_it_);
   }
 
   // Then remove old history if we have too much history saved.
   if (num_frames_history_ > kMaxFramesHistory) {
     frames_.erase(frames_.begin());
     --num_frames_history_;
   }
 }
 
 bool FrameBuffer::UpdateFrameInfoWithIncomingFrame(const FrameObject& frame,
                                                    FrameMap::iterator info) {
+  TRACE_EVENT0("webrtc", "FrameBuffer::UpdateFrameInfoWithIncomingFrame");
   FrameKey key(frame.picture_id, frame.spatial_layer);
   info->second.num_missing_continuous = frame.num_references;
   info->second.num_missing_decodable = frame.num_references;
 
   RTC_DCHECK(last_decoded_frame_it_ == frames_.end() ||
              last_decoded_frame_it_->first < info->first);
 
   // Check how many dependencies that have already been fulfilled.
   for (size_t i = 0; i < frame.num_references; ++i) {
     FrameKey ref_key(frame.references[i], frame.spatial_layer);
@@ skipping 52 matching lines @@
                   ref_info->second.num_missing_decodable);
   }
 
   RTC_DCHECK_LE(info->second.num_missing_continuous,
                 info->second.num_missing_decodable);
 
   return true;
 }
 
 void FrameBuffer::UpdateJitterDelay() {
+  TRACE_EVENT0("webrtc", "FrameBuffer::UpdateJitterDelay");
   if (!stats_callback_)
     return;
 
   int decode_ms;
   int max_decode_ms;
   int current_delay_ms;
   int target_delay_ms;
   int jitter_buffer_ms;
   int min_playout_delay_ms;
   int render_delay_ms;
   if (timing_->GetTimings(&decode_ms, &max_decode_ms, &current_delay_ms,
                           &target_delay_ms, &jitter_buffer_ms,
                           &min_playout_delay_ms, &render_delay_ms)) {
     stats_callback_->OnFrameBufferTimingsUpdated(
         decode_ms, max_decode_ms, current_delay_ms, target_delay_ms,
         jitter_buffer_ms, min_playout_delay_ms, render_delay_ms);
   }
 }
 
 void FrameBuffer::ClearFramesAndHistory() {
+  TRACE_EVENT0("webrtc", "FrameBuffer::UpdateJitterDelay");
   frames_.clear();
   last_decoded_frame_it_ = frames_.end();
   last_continuous_frame_it_ = frames_.end();
   next_frame_it_ = frames_.end();
   num_frames_history_ = 0;
   num_frames_buffered_ = 0;
 }
 
 }  // namespace video_coding
 }  // namespace webrtc