1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
|
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 09ca53ac94..8d61025912 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<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;
@@ -78,23 +84,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;
}
}
@@ -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/video/receive_statistics_proxy.cc b/video/receive_statistics_proxy.cc
index a0f19999d8..1764308c0a 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 49b7d06419..d9f7fcbe95 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"
@@ -1259,6 +1260,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 e6e16db752..8d880ca0ee 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 @@ absl::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 @@ absl::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();
|
