Quelle  0067.patch   Sprache: unbekannt

From: Andreas Pehrson <apehrson@mozilla.com>
Date: Thu, 6 Jan 2022 00:16:00 +0000
Subject: Bug 1748458 - Add TRACE_EVENTs for dropped frames and packets for
 received video. r=bwc

This lets us see in the profiler how many received frames and packets we decide
to drop and the reasons why.

Differential Revision: https://phabricator.services.mozilla.com/D135062
Mercurial Revision: https://hg.mozilla.org/mozilla-central/rev/08e252da94c4752eccfd845eef13d8517953cc6a

Also includes:

Bug 1804288 - (fix-de7ae5755b) reimplement Bug 1748458 - Add TRACE_EVENTs for dropped frames and packets for received video. r=pehrsons

Differential Revision: https://phabricator.services.mozilla.com/D163960
Mercurial Revision: https://hg.mozilla.org/mozilla-central/rev/8e9a326a99cd5eaa6e447ff57c01ad9d79a09744
---
 api/video/frame_buffer.cc               | 33 +++++++++++++++++++++++++
 video/receive_statistics_proxy.cc       | 11 +++++++++
 video/rtp_video_stream_receiver2.cc     |  4 +++
 video/video_stream_buffer_controller.cc |  7 ++++++
 4 files changed, 55 insertions(+)

diff --git a/api/video/frame_buffer.cc b/api/video/frame_buffer.cc
index 4981acf0ca..f0c48f3702 100644
--- a/api/video/frame_buffer.cc
+++ b/api/video/frame_buffer.cc
@@ -25,6 +25,7 @@
 #include "api/video/encoded_frame.h"
 #include "rtc_base/logging.h"
 #include "rtc_base/numerics/sequence_number_util.h"
+#include "rtc_base/trace_event.h"
 
 namespace webrtc {
 namespace {
@@ -77,7 +78,12 @@ FrameBuffer::FrameBuffer(int max_size,
       decoded_frame_history_(max_decode_history) {}
 
 bool FrameBuffer::InsertFrame(std::unique_ptr<EncodedFrame> frame) {
+  const uint32_t ssrc =
+      frame->PacketInfos().empty() ? 0 : frame->PacketInfos()[0].ssrc();
   if (!ValidReferences(*frame)) {
+    TRACE_EVENT2("webrtc",
+                 "FrameBuffer::InsertFrame Frame dropped (Invalid references)",
+                 "remote_ssrc", ssrc, "frame_id", frame->Id());
     RTC_DLOG(LS_WARNING) << "Frame " << frame->Id()
                          << " has invalid references, dropping frame.";
     return false;
@@ -87,23 +93,35 @@ bool FrameBuffer::InsertFrame(std::unique_ptr<EncodedFrame> frame) {
     if (legacy_frame_id_jump_behavior_ && frame->is_keyframe() &&
         AheadOf(frame->RtpTimestamp(),
                 *decoded_frame_history_.GetLastDecodedFrameTimestamp())) {
+      TRACE_EVENT2("webrtc",
+                   "FrameBuffer::InsertFrame Frames dropped (OOO + PicId jump)",
+                   "remote_ssrc", ssrc, "frame_id", frame->Id());
       RTC_DLOG(LS_WARNING)
           << "Keyframe " << frame->Id()
           << " has newer timestamp but older picture id, clearing buffer.";
       Clear();
     } else {
       // Already decoded past this frame.
+      TRACE_EVENT2("webrtc",
+                   "FrameBuffer::InsertFrame Frame dropped (Out of order)",
+                   "remote_ssrc", ssrc, "frame_id", frame->Id());
       return false;
     }
   }
 
   if (frames_.size() == max_size_) {
     if (frame->is_keyframe()) {
+      TRACE_EVENT2("webrtc",
+                   "FrameBuffer::InsertFrame Frames dropped (KF + Full buffer)",
+                   "remote_ssrc", ssrc, "frame_id", frame->Id());
       RTC_DLOG(LS_WARNING) << "Keyframe " << frame->Id()
                            << " inserted into full buffer, clearing buffer.";
       Clear();
     } else {
       // No space for this frame.
+      TRACE_EVENT2("webrtc",
+                   "FrameBuffer::InsertFrame Frame dropped (Full buffer)",
+                   "remote_ssrc", ssrc, "frame_id", frame->Id());
       return false;
     }
   }
@@ -158,16 +176,31 @@ void FrameBuffer::DropNextDecodableTemporalUnit() {
 
 void FrameBuffer::UpdateDroppedFramesAndDiscardedPackets(FrameIterator begin_it,
                                                          FrameIterator end_it) {
+  uint32_t dropped_ssrc = 0;
+  int64_t dropped_frame_id = 0;
   unsigned int num_discarded_packets = 0;
   unsigned int num_dropped_frames =
       std::count_if(begin_it, end_it, [&](const auto& f) {
         if (f.second.encoded_frame) {
           const auto& packetInfos = f.second.encoded_frame->PacketInfos();
+          dropped_frame_id = f.first;
+          if (!packetInfos.empty()) {
+            dropped_ssrc = packetInfos[0].ssrc();
+          }
           num_discarded_packets += packetInfos.size();
         }
         return f.second.encoded_frame != nullptr;
       });
 
+  if (num_dropped_frames > 0) {
+    TRACE_EVENT2("webrtc", "FrameBuffer Dropping Old Frames", "remote_ssrc",
+                 dropped_ssrc, "frame_id", dropped_frame_id);
+  }
+  if (num_discarded_packets > 0) {
+    TRACE_EVENT2("webrtc", "FrameBuffer Discarding Old Packets", "remote_ssrc",
+                 dropped_ssrc, "frame_id", dropped_frame_id);
+  }
+
   num_dropped_frames_ += num_dropped_frames;
   num_discarded_packets_ += num_discarded_packets;
 }
diff --git a/video/receive_statistics_proxy.cc b/video/receive_statistics_proxy.cc
index 84f4bfcae1..aec3a25df7 100644
--- a/video/receive_statistics_proxy.cc
+++ b/video/receive_statistics_proxy.cc
@@ -20,6 +20,7 @@
 #include "rtc_base/strings/string_builder.h"
 #include "rtc_base/thread.h"
 #include "rtc_base/time_utils.h"
+#include "rtc_base/trace_event.h"
 #include "system_wrappers/include/clock.h"
 #include "system_wrappers/include/metrics.h"
 #include "video/video_receive_stream2.h"
@@ -767,6 +768,9 @@ void ReceiveStatisticsProxy::OnCompleteFrame(bool is_keyframe,
                                              VideoContentType content_type) {
   RTC_DCHECK_RUN_ON(&main_thread_);
 
+  TRACE_EVENT2("webrtc", "ReceiveStatisticsProxy::OnCompleteFrame",
+               "remote_ssrc", remote_ssrc_, "is_keyframe", is_keyframe);
+
   // Content type extension is set only for keyframes and should be propagated
   // for all the following delta frames. Here we may receive frames out of order
   // and miscategorise some delta frames near the layer switch.
@@ -792,6 +796,8 @@ void ReceiveStatisticsProxy::OnCompleteFrame(bool is_keyframe,
 void ReceiveStatisticsProxy::OnDroppedFrames(uint32_t frames_dropped) {
   // Can be called on either the decode queue or the worker thread
   // See FrameBuffer2 for more details.
+  TRACE_EVENT2("webrtc", "ReceiveStatisticsProxy::OnDroppedFrames",
+               "remote_ssrc", remote_ssrc_, "frames_dropped", frames_dropped);
   worker_thread_->PostTask(
       SafeTask(task_safety_.flag(), [frames_dropped, this]() {
         RTC_DCHECK_RUN_ON(&main_thread_);
@@ -802,6 +808,9 @@ void ReceiveStatisticsProxy::OnDroppedFrames(uint32_t frames_dropped) {
 void ReceiveStatisticsProxy::OnDiscardedPackets(uint32_t packets_discarded) {
   // Can be called on either the decode queue or the worker thread
   // See FrameBuffer2 for more details.
+  TRACE_EVENT2("webrtc", "ReceiveStatisticsProxy::OnDiscardedPackets",
+               "remote_ssrc", remote_ssrc_, "packets_discarded",
+               packets_discarded);
   worker_thread_->PostTask(
       SafeTask(task_safety_.flag(), [packets_discarded, this]() {
         RTC_DCHECK_RUN_ON(&main_thread_);
@@ -830,6 +839,8 @@ void ReceiveStatisticsProxy::OnStreamInactive() {
 
 void ReceiveStatisticsProxy::OnRttUpdate(int64_t avg_rtt_ms) {
   RTC_DCHECK_RUN_ON(&main_thread_);
+  TRACE_EVENT2("webrtc", "ReceiveStatisticsProxy::OnRttUpdate",
+               "remote_ssrc", remote_ssrc_, "avg_rtt_ms", avg_rtt_ms);
   avg_rtt_ms_ = avg_rtt_ms;
 }
 
diff --git a/video/rtp_video_stream_receiver2.cc b/video/rtp_video_stream_receiver2.cc
index d599fa2f23..23c24c2c45 100644
--- a/video/rtp_video_stream_receiver2.cc
+++ b/video/rtp_video_stream_receiver2.cc
@@ -49,6 +49,7 @@
 #include "rtc_base/checks.h"
 #include "rtc_base/logging.h"
 #include "rtc_base/strings/string_builder.h"
+#include "rtc_base/trace_event.h"
 #include "system_wrappers/include/metrics.h"
 #include "system_wrappers/include/ntp_time.h"
 
@@ -1271,6 +1272,9 @@ void RtpVideoStreamReceiver2::FrameDecoded(int64_t picture_id) {
                         packet_infos_.upper_bound(unwrapped_rtp_seq_num));
     uint32_t num_packets_cleared = packet_buffer_.ClearTo(seq_num);
     if (num_packets_cleared > 0) {
+      TRACE_EVENT2("webrtc",
+                   "RtpVideoStreamReceiver2::FrameDecoded Cleared Old Packets",
+                   "remote_ssrc", config_.rtp.remote_ssrc, "seq_num", seq_num);
       vcm_receive_statistics_->OnDiscardedPackets(num_packets_cleared);
     }
     reference_finder_->ClearTo(seq_num);
diff --git a/video/video_stream_buffer_controller.cc b/video/video_stream_buffer_controller.cc
index 01063b12f7..e12ce75ba0 100644
--- a/video/video_stream_buffer_controller.cc
+++ b/video/video_stream_buffer_controller.cc
@@ -31,6 +31,7 @@
 #include "rtc_base/checks.h"
 #include "rtc_base/logging.h"
 #include "rtc_base/thread_annotations.h"
+#include "rtc_base/trace_event.h"
 #include "video/frame_decode_scheduler.h"
 #include "video/frame_decode_timing.h"
 #include "video/task_queue_frame_decode_scheduler.h"
@@ -152,6 +153,9 @@ std::optional<int64_t> VideoStreamBufferController::InsertFrame(
     std::unique_ptr<EncodedFrame> frame) {
   RTC_DCHECK_RUN_ON(&worker_sequence_checker_);
   FrameMetadata metadata(*frame);
+  const uint32_t ssrc =
+      frame->PacketInfos().empty() ? 0 : frame->PacketInfos()[0].ssrc();
+  const int64_t frameId = frame->Id();
   int complete_units = buffer_->GetTotalNumberOfContinuousTemporalUnits();
   if (buffer_->InsertFrame(std::move(frame))) {
     RTC_DCHECK(metadata.receive_time) << "Frame receive time must be set!";
@@ -162,6 +166,9 @@ std::optional<int64_t> VideoStreamBufferController::InsertFrame(
                                  *metadata.receive_time);
     }
     if (complete_units < buffer_->GetTotalNumberOfContinuousTemporalUnits()) {
+      TRACE_EVENT2("webrtc",
+                   "VideoStreamBufferController::InsertFrame Frame Complete",
+                   "remote_ssrc", ssrc, "frame_id", frameId);
       stats_proxy_->OnCompleteFrame(metadata.is_keyframe, metadata.size,
                                     metadata.contentType);
       MaybeScheduleFrameForRelease();