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
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
|
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 +++++++++++++++++++++++++
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<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->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<EncodedFrame> 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<EncodedFrame> 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<EncodedFrame> 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<EncodedFrame> 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<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!";
@@ -149,6 +153,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();
--
2.34.1
|
