From: Andreas Pehrson 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 +++++++++++++++++++++++++ modules/video_coding/frame_buffer2.cc | 25 +++++++++++++++++++ video/receive_statistics_proxy2.cc | 11 +++++++++ video/rtp_video_stream_receiver2.cc | 4 +++ video/video_stream_buffer_controller.cc | 7 ++++++ 5 files changed, 80 insertions(+) diff --git a/api/video/frame_buffer.cc b/api/video/frame_buffer.cc index 8267b8e6cb..f5d93f5f76 100644 --- a/api/video/frame_buffer.cc +++ b/api/video/frame_buffer.cc @@ -16,6 +16,7 @@ #include "absl/container/inlined_vector.h" #include "rtc_base/logging.h" #include "rtc_base/numerics/sequence_number_util.h" +#include "rtc_base/trace_event.h" namespace webrtc { namespace { @@ -68,7 +69,12 @@ FrameBuffer::FrameBuffer(int max_size, decoded_frame_history_(max_decode_history) {} bool FrameBuffer::InsertFrame(std::unique_ptr 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; @@ -78,23 +84,35 @@ bool FrameBuffer::InsertFrame(std::unique_ptr frame) { if (legacy_frame_id_jump_behavior_ && frame->is_keyframe() && AheadOf(frame->Timestamp(), *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; } } @@ -149,16 +167,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/modules/video_coding/frame_buffer2.cc b/modules/video_coding/frame_buffer2.cc index b289663eec..a70b143a29 100644 --- a/modules/video_coding/frame_buffer2.cc +++ b/modules/video_coding/frame_buffer2.cc @@ -371,9 +371,14 @@ int64_t FrameBuffer::InsertFrame(std::unique_ptr frame) { MutexLock lock(&mutex_); + const auto& pis = frame->PacketInfos(); int64_t last_continuous_frame_id = last_continuous_frame_.value_or(-1); if (!ValidReferences(*frame)) { + TRACE_EVENT2("webrtc", + "FrameBuffer::InsertFrame Frame dropped (Invalid references)", + "remote_ssrc", pis.empty() ? 0 : pis[0].ssrc(), "picture_id", + frame->Id()); RTC_LOG(LS_WARNING) << "Frame " << frame->Id() << " has invalid frame references, dropping frame."; return last_continuous_frame_id; @@ -381,11 +386,19 @@ int64_t FrameBuffer::InsertFrame(std::unique_ptr frame) { if (frames_.size() >= kMaxFramesBuffered) { if (frame->is_keyframe()) { + TRACE_EVENT2("webrtc", + "FrameBuffer::InsertFrame Frames dropped (KF + Full buffer)", + "remote_ssrc", pis.empty() ? 0 : pis[0].ssrc(), "picture_id", + frame->Id()); RTC_LOG(LS_WARNING) << "Inserting keyframe " << frame->Id() << " but buffer is full, clearing" " buffer and inserting the frame."; ClearFramesAndHistory(); } else { + TRACE_EVENT2("webrtc", + "FrameBuffer::InsertFrame Frame dropped (Full buffer)", + "remote_ssrc", pis.empty() ? 0 : pis[0].ssrc(), "picture_id", + frame->Id()); RTC_LOG(LS_WARNING) << "Frame " << frame->Id() << " could not be inserted due to the frame " "buffer being full, dropping frame."; @@ -404,11 +417,19 @@ int64_t FrameBuffer::InsertFrame(std::unique_ptr frame) { // reconfiguration or some other reason. Even though this is not according // to spec we can still continue to decode from this frame if it is a // keyframe. + TRACE_EVENT2("webrtc", + "FrameBuffer::InsertFrame Frames dropped (OOO + PicId jump)", + "remote_ssrc", pis.empty() ? 0 : pis[0].ssrc(), "picture_id", + frame->Id()); RTC_LOG(LS_WARNING) << "A jump in frame id was detected, clearing buffer."; ClearFramesAndHistory(); last_continuous_frame_id = -1; } else { + TRACE_EVENT2("webrtc", + "FrameBuffer::InsertFrame Frame dropped (Out of order)", + "remote_ssrc", pis.empty() ? 0 : pis[0].ssrc(), "picture_id", + frame->Id()); RTC_LOG(LS_WARNING) << "Frame " << frame->Id() << " inserted after frame " << *last_decoded_frame << " was handed off for decoding, dropping frame."; @@ -421,6 +442,10 @@ int64_t FrameBuffer::InsertFrame(std::unique_ptr frame) { // when the frame id make large jumps mid stream. if (!frames_.empty() && frame->Id() < frames_.begin()->first && frames_.rbegin()->first < frame->Id()) { + TRACE_EVENT2("webrtc", + "FrameBuffer::InsertFrame Frames dropped (PicId big-jump)", + "remote_ssrc", pis.empty() ? 0 : pis[0].ssrc(), "picture_id", + frame->Id()); RTC_LOG(LS_WARNING) << "A jump in frame id was detected, clearing buffer."; ClearFramesAndHistory(); last_continuous_frame_id = -1; diff --git a/video/receive_statistics_proxy2.cc b/video/receive_statistics_proxy2.cc index f5011c46ef..508c36eaaf 100644 --- a/video/receive_statistics_proxy2.cc +++ b/video/receive_statistics_proxy2.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" @@ -921,6 +922,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); + if (is_keyframe) { ++stats_.frame_counts.key_frames; } else { @@ -952,6 +956,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_); @@ -962,6 +968,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_); @@ -991,6 +1000,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 a5d5f637e5..eb0a7787ac 100644 --- a/video/rtp_video_stream_receiver2.cc +++ b/video/rtp_video_stream_receiver2.cc @@ -44,6 +44,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" @@ -1223,6 +1224,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 7e44eff39a..37724a8338 100644 --- a/video/video_stream_buffer_controller.cc +++ b/video/video_stream_buffer_controller.cc @@ -28,6 +28,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" @@ -139,6 +140,9 @@ absl::optional VideoStreamBufferController::InsertFrame( std::unique_ptr 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!"; @@ -149,6 +153,9 @@ absl::optional 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(); -- 2.34.1