1 /*
2 * Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
11 #include "rtc_tools/rtc_event_log_visualizer/analyzer.h"
12
13 #include <algorithm>
14 #include <cmath>
15 #include <limits>
16 #include <map>
17 #include <memory>
18 #include <string>
19 #include <utility>
20
21 #include "absl/algorithm/container.h"
22 #include "absl/functional/bind_front.h"
23 #include "absl/strings/string_view.h"
24 #include "api/function_view.h"
25 #include "api/network_state_predictor.h"
26 #include "api/transport/field_trial_based_config.h"
27 #include "api/transport/goog_cc_factory.h"
28 #include "call/audio_receive_stream.h"
29 #include "call/audio_send_stream.h"
30 #include "call/call.h"
31 #include "call/video_receive_stream.h"
32 #include "call/video_send_stream.h"
33 #include "logging/rtc_event_log/rtc_event_processor.h"
34 #include "logging/rtc_event_log/rtc_stream_config.h"
35 #include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
36 #include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
37 #include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
38 #include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
39 #include "modules/congestion_controller/include/receive_side_congestion_controller.h"
40 #include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
41 #include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
42 #include "modules/rtp_rtcp/source/rtcp_packet.h"
43 #include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
44 #include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
45 #include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
46 #include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
47 #include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
48 #include "modules/rtp_rtcp/source/rtp_header_extensions.h"
49 #include "modules/rtp_rtcp/source/rtp_rtcp_interface.h"
50 #include "rtc_base/checks.h"
51 #include "rtc_base/logging.h"
52 #include "rtc_base/numerics/sequence_number_util.h"
53 #include "rtc_base/rate_statistics.h"
54 #include "rtc_base/strings/string_builder.h"
55 #include "rtc_tools/rtc_event_log_visualizer/log_simulation.h"
56 #include "test/explicit_key_value_config.h"
57
58 namespace webrtc {
59
60 namespace {
61
SsrcToString(uint32_t ssrc)62 std::string SsrcToString(uint32_t ssrc) {
63 rtc::StringBuilder ss;
64 ss << "SSRC " << ssrc;
65 return ss.Release();
66 }
67
68 // Checks whether an SSRC is contained in the list of desired SSRCs.
69 // Note that an empty SSRC list matches every SSRC.
MatchingSsrc(uint32_t ssrc,const std::vector<uint32_t> & desired_ssrc)70 bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
71 if (desired_ssrc.empty())
72 return true;
73 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
74 desired_ssrc.end();
75 }
76
AbsSendTimeToMicroseconds(int64_t abs_send_time)77 double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
78 // The timestamp is a fixed point representation with 6 bits for seconds
79 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
80 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
81 // microseconds.
82 static constexpr double kTimestampToMicroSec =
83 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
84 return abs_send_time * kTimestampToMicroSec;
85 }
86
87 // Computes the difference `later` - `earlier` where `later` and `earlier`
88 // are counters that wrap at `modulus`. The difference is chosen to have the
89 // least absolute value. For example if `modulus` is 8, then the difference will
90 // be chosen in the range [-3, 4]. If `modulus` is 9, then the difference will
91 // be in [-4, 4].
WrappingDifference(uint32_t later,uint32_t earlier,int64_t modulus)92 int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
93 RTC_DCHECK_LE(1, modulus);
94 RTC_DCHECK_LT(later, modulus);
95 RTC_DCHECK_LT(earlier, modulus);
96 int64_t difference =
97 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
98 int64_t max_difference = modulus / 2;
99 int64_t min_difference = max_difference - modulus + 1;
100 if (difference > max_difference) {
101 difference -= modulus;
102 }
103 if (difference < min_difference) {
104 difference += modulus;
105 }
106 if (difference > max_difference / 2 || difference < min_difference / 2) {
107 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
108 << " expected to be in the range ("
109 << min_difference / 2 << "," << max_difference / 2
110 << ") but is " << difference
111 << ". Correct unwrapping is uncertain.";
112 }
113 return difference;
114 }
115
116 // This is much more reliable for outgoing streams than for incoming streams.
117 template <typename RtpPacketContainer>
EstimateRtpClockFrequency(const RtpPacketContainer & packets,int64_t end_time_us)118 absl::optional<uint32_t> EstimateRtpClockFrequency(
119 const RtpPacketContainer& packets,
120 int64_t end_time_us) {
121 RTC_CHECK(packets.size() >= 2);
122 SeqNumUnwrapper<uint32_t> unwrapper;
123 int64_t first_rtp_timestamp =
124 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
125 int64_t first_log_timestamp = packets[0].log_time_us();
126 int64_t last_rtp_timestamp = first_rtp_timestamp;
127 int64_t last_log_timestamp = first_log_timestamp;
128 for (size_t i = 1; i < packets.size(); i++) {
129 if (packets[i].log_time_us() > end_time_us)
130 break;
131 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
132 last_log_timestamp = packets[i].log_time_us();
133 }
134 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
135 RTC_LOG(LS_WARNING)
136 << "Failed to estimate RTP clock frequency: Stream too short. ("
137 << packets.size() << " packets, "
138 << last_log_timestamp - first_log_timestamp << " us)";
139 return absl::nullopt;
140 }
141 double duration =
142 static_cast<double>(last_log_timestamp - first_log_timestamp) /
143 kNumMicrosecsPerSec;
144 double estimated_frequency =
145 (last_rtp_timestamp - first_rtp_timestamp) / duration;
146 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
147 if (std::fabs(estimated_frequency - f) < 0.15 * f) {
148 return f;
149 }
150 }
151 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
152 << estimated_frequency
153 << " not close to any standard RTP frequency."
154 << " Last timestamp " << last_rtp_timestamp
155 << " first timestamp " << first_rtp_timestamp;
156 return absl::nullopt;
157 }
158
NetworkDelayDiff_AbsSendTime(const LoggedRtpPacketIncoming & old_packet,const LoggedRtpPacketIncoming & new_packet)159 absl::optional<double> NetworkDelayDiff_AbsSendTime(
160 const LoggedRtpPacketIncoming& old_packet,
161 const LoggedRtpPacketIncoming& new_packet) {
162 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
163 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
164 int64_t send_time_diff = WrappingDifference(
165 new_packet.rtp.header.extension.absoluteSendTime,
166 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
167 int64_t recv_time_diff =
168 new_packet.log_time_us() - old_packet.log_time_us();
169 double delay_change_us =
170 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
171 return delay_change_us / 1000;
172 } else {
173 return absl::nullopt;
174 }
175 }
176
NetworkDelayDiff_CaptureTime(const LoggedRtpPacketIncoming & old_packet,const LoggedRtpPacketIncoming & new_packet,const double sample_rate)177 absl::optional<double> NetworkDelayDiff_CaptureTime(
178 const LoggedRtpPacketIncoming& old_packet,
179 const LoggedRtpPacketIncoming& new_packet,
180 const double sample_rate) {
181 int64_t send_time_diff =
182 WrappingDifference(new_packet.rtp.header.timestamp,
183 old_packet.rtp.header.timestamp, 1ull << 32);
184 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
185
186 double delay_change =
187 static_cast<double>(recv_time_diff) / 1000 -
188 static_cast<double>(send_time_diff) / sample_rate * 1000;
189 if (delay_change < -10000 || 10000 < delay_change) {
190 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
191 RTC_LOG(LS_WARNING) << "Old capture time "
192 << old_packet.rtp.header.timestamp << ", received time "
193 << old_packet.log_time_us();
194 RTC_LOG(LS_WARNING) << "New capture time "
195 << new_packet.rtp.header.timestamp << ", received time "
196 << new_packet.log_time_us();
197 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
198 << static_cast<double>(recv_time_diff) /
199 kNumMicrosecsPerSec
200 << "s";
201 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
202 << static_cast<double>(send_time_diff) / sample_rate
203 << "s";
204 }
205 return delay_change;
206 }
207
208
209 template <typename T>
CreateRtcpTypeTimeSeries(const std::vector<T> & rtcp_list,AnalyzerConfig config,std::string rtcp_name,int category_id)210 TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
211 AnalyzerConfig config,
212 std::string rtcp_name,
213 int category_id) {
214 TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
215 for (const auto& rtcp : rtcp_list) {
216 float x = config.GetCallTimeSec(rtcp.timestamp);
217 float y = category_id;
218 time_series.points.emplace_back(x, y);
219 }
220 return time_series;
221 }
222
223 const char kUnknownEnumValue[] = "unknown";
224
225 const char kIceCandidateTypeLocal[] = "local";
226 const char kIceCandidateTypeStun[] = "stun";
227 const char kIceCandidateTypePrflx[] = "prflx";
228 const char kIceCandidateTypeRelay[] = "relay";
229
230 const char kProtocolUdp[] = "udp";
231 const char kProtocolTcp[] = "tcp";
232 const char kProtocolSsltcp[] = "ssltcp";
233 const char kProtocolTls[] = "tls";
234
235 const char kAddressFamilyIpv4[] = "ipv4";
236 const char kAddressFamilyIpv6[] = "ipv6";
237
238 const char kNetworkTypeEthernet[] = "ethernet";
239 const char kNetworkTypeLoopback[] = "loopback";
240 const char kNetworkTypeWifi[] = "wifi";
241 const char kNetworkTypeVpn[] = "vpn";
242 const char kNetworkTypeCellular[] = "cellular";
243
GetIceCandidateTypeAsString(webrtc::IceCandidateType type)244 std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
245 switch (type) {
246 case webrtc::IceCandidateType::kLocal:
247 return kIceCandidateTypeLocal;
248 case webrtc::IceCandidateType::kStun:
249 return kIceCandidateTypeStun;
250 case webrtc::IceCandidateType::kPrflx:
251 return kIceCandidateTypePrflx;
252 case webrtc::IceCandidateType::kRelay:
253 return kIceCandidateTypeRelay;
254 default:
255 return kUnknownEnumValue;
256 }
257 }
258
GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol)259 std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
260 switch (protocol) {
261 case webrtc::IceCandidatePairProtocol::kUdp:
262 return kProtocolUdp;
263 case webrtc::IceCandidatePairProtocol::kTcp:
264 return kProtocolTcp;
265 case webrtc::IceCandidatePairProtocol::kSsltcp:
266 return kProtocolSsltcp;
267 case webrtc::IceCandidatePairProtocol::kTls:
268 return kProtocolTls;
269 default:
270 return kUnknownEnumValue;
271 }
272 }
273
GetAddressFamilyAsString(webrtc::IceCandidatePairAddressFamily family)274 std::string GetAddressFamilyAsString(
275 webrtc::IceCandidatePairAddressFamily family) {
276 switch (family) {
277 case webrtc::IceCandidatePairAddressFamily::kIpv4:
278 return kAddressFamilyIpv4;
279 case webrtc::IceCandidatePairAddressFamily::kIpv6:
280 return kAddressFamilyIpv6;
281 default:
282 return kUnknownEnumValue;
283 }
284 }
285
GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type)286 std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
287 switch (type) {
288 case webrtc::IceCandidateNetworkType::kEthernet:
289 return kNetworkTypeEthernet;
290 case webrtc::IceCandidateNetworkType::kLoopback:
291 return kNetworkTypeLoopback;
292 case webrtc::IceCandidateNetworkType::kWifi:
293 return kNetworkTypeWifi;
294 case webrtc::IceCandidateNetworkType::kVpn:
295 return kNetworkTypeVpn;
296 case webrtc::IceCandidateNetworkType::kCellular:
297 return kNetworkTypeCellular;
298 default:
299 return kUnknownEnumValue;
300 }
301 }
302
GetCandidatePairLogDescriptionAsString(const LoggedIceCandidatePairConfig & config)303 std::string GetCandidatePairLogDescriptionAsString(
304 const LoggedIceCandidatePairConfig& config) {
305 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
306 // represents a pair of a local server-reflexive candidate on a WiFi network
307 // and a remote relay candidate using TCP as the relay protocol on a cell
308 // network, when the candidate pair communicates over UDP using IPv4.
309 rtc::StringBuilder ss;
310 std::string local_candidate_type =
311 GetIceCandidateTypeAsString(config.local_candidate_type);
312 std::string remote_candidate_type =
313 GetIceCandidateTypeAsString(config.remote_candidate_type);
314 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
315 local_candidate_type +=
316 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
317 }
318 ss << local_candidate_type << ":"
319 << GetNetworkTypeAsString(config.local_network_type) << ":"
320 << GetAddressFamilyAsString(config.local_address_family) << "->"
321 << remote_candidate_type << ":"
322 << GetAddressFamilyAsString(config.remote_address_family) << "@"
323 << GetProtocolAsString(config.candidate_pair_protocol);
324 return ss.Release();
325 }
326
GetDirectionAsString(PacketDirection direction)327 std::string GetDirectionAsString(PacketDirection direction) {
328 if (direction == kIncomingPacket) {
329 return "Incoming";
330 } else {
331 return "Outgoing";
332 }
333 }
334
GetDirectionAsShortString(PacketDirection direction)335 std::string GetDirectionAsShortString(PacketDirection direction) {
336 if (direction == kIncomingPacket) {
337 return "In";
338 } else {
339 return "Out";
340 }
341 }
342
343 } // namespace
344
EventLogAnalyzer(const ParsedRtcEventLog & log,bool normalize_time)345 EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
346 bool normalize_time)
347 : parsed_log_(log) {
348 config_.window_duration_ = TimeDelta::Millis(250);
349 config_.step_ = TimeDelta::Millis(10);
350 if (!log.start_log_events().empty()) {
351 config_.rtc_to_utc_offset_ = log.start_log_events()[0].utc_time() -
352 log.start_log_events()[0].log_time();
353 }
354 config_.normalize_time_ = normalize_time;
355 config_.begin_time_ = parsed_log_.first_timestamp();
356 config_.end_time_ = parsed_log_.last_timestamp();
357 if (config_.end_time_ < config_.begin_time_) {
358 RTC_LOG(LS_WARNING) << "No useful events in the log.";
359 config_.begin_time_ = config_.end_time_ = Timestamp::Zero();
360 }
361
362 RTC_LOG(LS_INFO) << "Log is "
363 << (parsed_log_.last_timestamp().ms() -
364 parsed_log_.first_timestamp().ms()) /
365 1000
366 << " seconds long.";
367 }
368
EventLogAnalyzer(const ParsedRtcEventLog & log,const AnalyzerConfig & config)369 EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
370 const AnalyzerConfig& config)
371 : parsed_log_(log), config_(config) {
372 RTC_LOG(LS_INFO) << "Log is "
373 << (parsed_log_.last_timestamp().ms() -
374 parsed_log_.first_timestamp().ms()) /
375 1000
376 << " seconds long.";
377 }
378
379 class BitrateObserver : public RemoteBitrateObserver {
380 public:
BitrateObserver()381 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
382
Update(NetworkControlUpdate update)383 void Update(NetworkControlUpdate update) {
384 if (update.target_rate) {
385 last_bitrate_bps_ = update.target_rate->target_rate.bps();
386 bitrate_updated_ = true;
387 }
388 }
389
OnReceiveBitrateChanged(const std::vector<uint32_t> & ssrcs,uint32_t bitrate)390 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
391 uint32_t bitrate) override {}
392
last_bitrate_bps() const393 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
GetAndResetBitrateUpdated()394 bool GetAndResetBitrateUpdated() {
395 bool bitrate_updated = bitrate_updated_;
396 bitrate_updated_ = false;
397 return bitrate_updated;
398 }
399
400 private:
401 uint32_t last_bitrate_bps_;
402 bool bitrate_updated_;
403 };
404
CreatePacketGraph(PacketDirection direction,Plot * plot)405 void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
406 Plot* plot) {
407 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
408 // Filter on SSRC.
409 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
410 continue;
411 }
412
413 TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
414 LineStyle::kBar);
415 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
416 return absl::optional<float>(packet.total_length);
417 };
418 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
419 return this->config_.GetCallTimeSec(packet.timestamp);
420 };
421 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
422 stream.packet_view, &time_series);
423 plot->AppendTimeSeries(std::move(time_series));
424 }
425
426 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
427 "Time (s)", kLeftMargin, kRightMargin);
428 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
429 kTopMargin);
430 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
431 }
432
CreateRtcpTypeGraph(PacketDirection direction,Plot * plot)433 void EventLogAnalyzer::CreateRtcpTypeGraph(PacketDirection direction,
434 Plot* plot) {
435 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
436 parsed_log_.transport_feedbacks(direction), config_, "TWCC", 1));
437 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
438 parsed_log_.receiver_reports(direction), config_, "RR", 2));
439 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
440 parsed_log_.sender_reports(direction), config_, "SR", 3));
441 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
442 parsed_log_.extended_reports(direction), config_, "XR", 4));
443 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.nacks(direction),
444 config_, "NACK", 5));
445 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.rembs(direction),
446 config_, "REMB", 6));
447 plot->AppendTimeSeries(
448 CreateRtcpTypeTimeSeries(parsed_log_.firs(direction), config_, "FIR", 7));
449 plot->AppendTimeSeries(
450 CreateRtcpTypeTimeSeries(parsed_log_.plis(direction), config_, "PLI", 8));
451 plot->AppendTimeSeries(
452 CreateRtcpTypeTimeSeries(parsed_log_.byes(direction), config_, "BYE", 9));
453 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
454 "Time (s)", kLeftMargin, kRightMargin);
455 plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
456 plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
457 plot->SetYAxisTickLabels({{1, "TWCC"},
458 {2, "RR"},
459 {3, "SR"},
460 {4, "XR"},
461 {5, "NACK"},
462 {6, "REMB"},
463 {7, "FIR"},
464 {8, "PLI"},
465 {9, "BYE"}});
466 }
467
468 template <typename IterableType>
CreateAccumulatedPacketsTimeSeries(Plot * plot,const IterableType & packets,const std::string & label)469 void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
470 Plot* plot,
471 const IterableType& packets,
472 const std::string& label) {
473 TimeSeries time_series(label, LineStyle::kStep);
474 for (size_t i = 0; i < packets.size(); i++) {
475 float x = config_.GetCallTimeSec(packets[i].log_time());
476 time_series.points.emplace_back(x, i + 1);
477 }
478 plot->AppendTimeSeries(std::move(time_series));
479 }
480
CreateAccumulatedPacketsGraph(PacketDirection direction,Plot * plot)481 void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
482 Plot* plot) {
483 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
484 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
485 continue;
486 std::string label = std::string("RTP ") +
487 GetStreamName(parsed_log_, direction, stream.ssrc);
488 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
489 }
490 std::string label =
491 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
492 if (direction == kIncomingPacket) {
493 CreateAccumulatedPacketsTimeSeries(
494 plot, parsed_log_.incoming_rtcp_packets(), label);
495 } else {
496 CreateAccumulatedPacketsTimeSeries(
497 plot, parsed_log_.outgoing_rtcp_packets(), label);
498 }
499
500 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
501 "Time (s)", kLeftMargin, kRightMargin);
502 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
503 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
504 " RTP/RTCP packets");
505 }
506
CreatePacketRateGraph(PacketDirection direction,Plot * plot)507 void EventLogAnalyzer::CreatePacketRateGraph(PacketDirection direction,
508 Plot* plot) {
509 auto CountPackets = [](auto packet) { return 1.0; };
510 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
511 // Filter on SSRC.
512 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
513 continue;
514 }
515 TimeSeries time_series(
516 std::string("RTP ") +
517 GetStreamName(parsed_log_, direction, stream.ssrc),
518 LineStyle::kLine);
519 MovingAverage<LoggedRtpPacket, double>(CountPackets, stream.packet_view,
520 config_, &time_series);
521 plot->AppendTimeSeries(std::move(time_series));
522 }
523 TimeSeries time_series(
524 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")",
525 LineStyle::kLine);
526 if (direction == kIncomingPacket) {
527 MovingAverage<LoggedRtcpPacketIncoming, double>(
528 CountPackets, parsed_log_.incoming_rtcp_packets(), config_,
529 &time_series);
530 } else {
531 MovingAverage<LoggedRtcpPacketOutgoing, double>(
532 CountPackets, parsed_log_.outgoing_rtcp_packets(), config_,
533 &time_series);
534 }
535 plot->AppendTimeSeries(std::move(time_series));
536
537 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
538 "Time (s)", kLeftMargin, kRightMargin);
539 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
540 kTopMargin);
541 plot->SetTitle("Rate of " + GetDirectionAsString(direction) +
542 " RTP/RTCP packets");
543 }
544
CreateTotalPacketRateGraph(PacketDirection direction,Plot * plot)545 void EventLogAnalyzer::CreateTotalPacketRateGraph(PacketDirection direction,
546 Plot* plot) {
547 // Contains a log timestamp to enable counting logged events of different
548 // types using MovingAverage().
549 class LogTime {
550 public:
551 explicit LogTime(Timestamp log_time) : log_time_(log_time) {}
552 Timestamp log_time() const { return log_time_; }
553
554 private:
555 Timestamp log_time_;
556 };
557 std::vector<LogTime> packet_times;
558 auto handle_rtp = [&](const LoggedRtpPacket& packet) {
559 packet_times.emplace_back(packet.log_time());
560 };
561 RtcEventProcessor process;
562 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
563 process.AddEvents(stream.packet_view, handle_rtp);
564 }
565 if (direction == kIncomingPacket) {
566 auto handle_incoming_rtcp = [&](const LoggedRtcpPacketIncoming& packet) {
567 packet_times.emplace_back(packet.log_time());
568 };
569 process.AddEvents(parsed_log_.incoming_rtcp_packets(),
570 handle_incoming_rtcp);
571 } else {
572 auto handle_outgoing_rtcp = [&](const LoggedRtcpPacketOutgoing& packet) {
573 packet_times.emplace_back(packet.log_time());
574 };
575 process.AddEvents(parsed_log_.outgoing_rtcp_packets(),
576 handle_outgoing_rtcp);
577 }
578 process.ProcessEventsInOrder();
579 TimeSeries time_series(std::string("Total ") + "(" +
580 GetDirectionAsShortString(direction) + ") packets",
581 LineStyle::kLine);
582 MovingAverage<LogTime, uint64_t>([](auto packet) { return 1; }, packet_times,
583 config_, &time_series);
584 plot->AppendTimeSeries(std::move(time_series));
585
586 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
587 "Time (s)", kLeftMargin, kRightMargin);
588 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
589 kTopMargin);
590 plot->SetTitle("Rate of all " + GetDirectionAsString(direction) +
591 " RTP/RTCP packets");
592 }
593
594 // For each SSRC, plot the time between the consecutive playouts.
CreatePlayoutGraph(Plot * plot)595 void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
596 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
597 uint32_t ssrc = playout_stream.first;
598 if (!MatchingSsrc(ssrc, desired_ssrc_))
599 continue;
600 absl::optional<int64_t> last_playout_ms;
601 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
602 for (const auto& playout_event : playout_stream.second) {
603 float x = config_.GetCallTimeSec(playout_event.log_time());
604 int64_t playout_time_ms = playout_event.log_time_ms();
605 // If there were no previous playouts, place the point on the x-axis.
606 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
607 time_series.points.push_back(TimeSeriesPoint(x, y));
608 last_playout_ms.emplace(playout_time_ms);
609 }
610 plot->AppendTimeSeries(std::move(time_series));
611 }
612
613 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
614 "Time (s)", kLeftMargin, kRightMargin);
615 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
616 kTopMargin);
617 plot->SetTitle("Audio playout");
618 }
619
620 // For audio SSRCs, plot the audio level.
CreateAudioLevelGraph(PacketDirection direction,Plot * plot)621 void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
622 Plot* plot) {
623 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
624 if (!IsAudioSsrc(parsed_log_, direction, stream.ssrc))
625 continue;
626 TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
627 LineStyle::kLine);
628 for (auto& packet : stream.packet_view) {
629 if (packet.header.extension.hasAudioLevel) {
630 float x = config_.GetCallTimeSec(packet.log_time());
631 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
632 // Here we convert it to dBov.
633 float y = static_cast<float>(-packet.header.extension.audioLevel);
634 time_series.points.emplace_back(TimeSeriesPoint(x, y));
635 }
636 }
637 plot->AppendTimeSeries(std::move(time_series));
638 }
639
640 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
641 "Time (s)", kLeftMargin, kRightMargin);
642 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
643 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
644 }
645
646 // For each SSRC, plot the sequence number difference between consecutive
647 // incoming packets.
CreateSequenceNumberGraph(Plot * plot)648 void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
649 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
650 // Filter on SSRC.
651 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
652 continue;
653 }
654
655 TimeSeries time_series(
656 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc),
657 LineStyle::kBar);
658 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
659 const LoggedRtpPacketIncoming& new_packet) {
660 int64_t diff =
661 WrappingDifference(new_packet.rtp.header.sequenceNumber,
662 old_packet.rtp.header.sequenceNumber, 1ul << 16);
663 return diff;
664 };
665 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
666 return this->config_.GetCallTimeSec(packet.log_time());
667 };
668 ProcessPairs<LoggedRtpPacketIncoming, float>(
669 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
670 &time_series);
671 plot->AppendTimeSeries(std::move(time_series));
672 }
673
674 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
675 "Time (s)", kLeftMargin, kRightMargin);
676 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
677 kTopMargin);
678 plot->SetTitle("Incoming sequence number delta");
679 }
680
CreateIncomingPacketLossGraph(Plot * plot)681 void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
682 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
683 const std::vector<LoggedRtpPacketIncoming>& packets =
684 stream.incoming_packets;
685 // Filter on SSRC.
686 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.empty()) {
687 continue;
688 }
689
690 TimeSeries time_series(
691 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc),
692 LineStyle::kLine, PointStyle::kHighlight);
693 // TODO(terelius): Should the window and step size be read from the class
694 // instead?
695 const TimeDelta kWindow = TimeDelta::Millis(1000);
696 const TimeDelta kStep = TimeDelta::Millis(1000);
697 SeqNumUnwrapper<uint16_t> unwrapper_;
698 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
699 size_t window_index_begin = 0;
700 size_t window_index_end = 0;
701 uint64_t highest_seq_number =
702 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
703 uint64_t highest_prior_seq_number =
704 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
705
706 for (Timestamp t = config_.begin_time_; t < config_.end_time_ + kStep;
707 t += kStep) {
708 while (window_index_end < packets.size() &&
709 packets[window_index_end].rtp.log_time() < t) {
710 uint64_t sequence_number = unwrapper_.Unwrap(
711 packets[window_index_end].rtp.header.sequenceNumber);
712 highest_seq_number = std::max(highest_seq_number, sequence_number);
713 ++window_index_end;
714 }
715 while (window_index_begin < packets.size() &&
716 packets[window_index_begin].rtp.log_time() < t - kWindow) {
717 uint64_t sequence_number = prior_unwrapper_.Unwrap(
718 packets[window_index_begin].rtp.header.sequenceNumber);
719 highest_prior_seq_number =
720 std::max(highest_prior_seq_number, sequence_number);
721 ++window_index_begin;
722 }
723 float x = config_.GetCallTimeSec(t);
724 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
725 if (expected_packets > 0) {
726 int64_t received_packets = window_index_end - window_index_begin;
727 int64_t lost_packets = expected_packets - received_packets;
728 float y = static_cast<float>(lost_packets) / expected_packets * 100;
729 time_series.points.emplace_back(x, y);
730 }
731 }
732 plot->AppendTimeSeries(std::move(time_series));
733 }
734
735 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
736 "Time (s)", kLeftMargin, kRightMargin);
737 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
738 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
739 }
740
CreateIncomingDelayGraph(Plot * plot)741 void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
742 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
743 // Filter on SSRC.
744 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
745 IsRtxSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) {
746 continue;
747 }
748
749 const std::vector<LoggedRtpPacketIncoming>& packets =
750 stream.incoming_packets;
751 if (packets.size() < 100) {
752 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
753 << packets.size() << " packets in the stream.";
754 continue;
755 }
756 int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
757 absl::optional<uint32_t> estimated_frequency =
758 EstimateRtpClockFrequency(packets, segment_end_us);
759 if (!estimated_frequency)
760 continue;
761 const double frequency_hz = *estimated_frequency;
762 if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc) &&
763 frequency_hz != 90000) {
764 RTC_LOG(LS_WARNING)
765 << "Video stream should use a 90 kHz clock but appears to use "
766 << frequency_hz / 1000 << ". Discarding.";
767 continue;
768 }
769
770 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
771 return this->config_.GetCallTimeSec(packet.log_time());
772 };
773 auto ToNetworkDelay = [frequency_hz](
774 const LoggedRtpPacketIncoming& old_packet,
775 const LoggedRtpPacketIncoming& new_packet) {
776 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
777 };
778
779 TimeSeries capture_time_data(
780 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) +
781 " capture-time",
782 LineStyle::kLine);
783 AccumulatePairs<LoggedRtpPacketIncoming, double>(
784 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
785 plot->AppendTimeSeries(std::move(capture_time_data));
786
787 TimeSeries send_time_data(
788 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) +
789 " abs-send-time",
790 LineStyle::kLine);
791 AccumulatePairs<LoggedRtpPacketIncoming, double>(
792 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
793 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
794 }
795
796 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
797 "Time (s)", kLeftMargin, kRightMargin);
798 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
799 plot->SetTitle("Incoming network delay (relative to first packet)");
800 }
801
802 // Plot the fraction of packets lost (as perceived by the loss-based BWE).
CreateFractionLossGraph(Plot * plot)803 void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
804 TimeSeries time_series("Fraction lost", LineStyle::kLine,
805 PointStyle::kHighlight);
806 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
807 float x = config_.GetCallTimeSec(bwe_update.log_time());
808 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
809 time_series.points.emplace_back(x, y);
810 }
811
812 plot->AppendTimeSeries(std::move(time_series));
813 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
814 "Time (s)", kLeftMargin, kRightMargin);
815 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
816 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
817 }
818
819 // Plot the total bandwidth used by all RTP streams.
CreateTotalIncomingBitrateGraph(Plot * plot)820 void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
821 // TODO(terelius): This could be provided by the parser.
822 std::multimap<Timestamp, size_t> packets_in_order;
823 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
824 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
825 packets_in_order.insert(
826 std::make_pair(packet.rtp.log_time(), packet.rtp.total_length));
827 }
828
829 auto window_begin = packets_in_order.begin();
830 auto window_end = packets_in_order.begin();
831 size_t bytes_in_window = 0;
832
833 if (!packets_in_order.empty()) {
834 // Calculate a moving average of the bitrate and store in a TimeSeries.
835 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
836 for (Timestamp time = config_.begin_time_;
837 time < config_.end_time_ + config_.step_; time += config_.step_) {
838 while (window_end != packets_in_order.end() && window_end->first < time) {
839 bytes_in_window += window_end->second;
840 ++window_end;
841 }
842 while (window_begin != packets_in_order.end() &&
843 window_begin->first < time - config_.window_duration_) {
844 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
845 bytes_in_window -= window_begin->second;
846 ++window_begin;
847 }
848 float window_duration_in_seconds =
849 static_cast<float>(config_.window_duration_.us()) /
850 kNumMicrosecsPerSec;
851 float x = config_.GetCallTimeSec(time);
852 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
853 bitrate_series.points.emplace_back(x, y);
854 }
855 plot->AppendTimeSeries(std::move(bitrate_series));
856 }
857
858 // Overlay the outgoing REMB over incoming bitrate.
859 TimeSeries remb_series("Remb", LineStyle::kStep);
860 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
861 float x = config_.GetCallTimeSec(rtcp.log_time());
862 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
863 remb_series.points.emplace_back(x, y);
864 }
865 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
866
867 if (!parsed_log_.generic_packets_received().empty()) {
868 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
869 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
870 return packet.packet_length * 8.0 / 1000.0;
871 };
872 MovingAverage<LoggedGenericPacketReceived, double>(
873 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
874 &time_series);
875 plot->AppendTimeSeries(std::move(time_series));
876 }
877
878 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
879 "Time (s)", kLeftMargin, kRightMargin);
880 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
881 plot->SetTitle("Incoming RTP bitrate");
882 }
883
884 // Plot the total bandwidth used by all RTP streams.
CreateTotalOutgoingBitrateGraph(Plot * plot,bool show_detector_state,bool show_alr_state,bool show_link_capacity)885 void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(
886 Plot* plot,
887 bool show_detector_state,
888 bool show_alr_state,
889 bool show_link_capacity) {
890 // TODO(terelius): This could be provided by the parser.
891 std::multimap<Timestamp, size_t> packets_in_order;
892 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
893 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
894 packets_in_order.insert(
895 std::make_pair(packet.rtp.log_time(), packet.rtp.total_length));
896 }
897
898 auto window_begin = packets_in_order.begin();
899 auto window_end = packets_in_order.begin();
900 size_t bytes_in_window = 0;
901
902 if (!packets_in_order.empty()) {
903 // Calculate a moving average of the bitrate and store in a TimeSeries.
904 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
905 for (Timestamp time = config_.begin_time_;
906 time < config_.end_time_ + config_.step_; time += config_.step_) {
907 while (window_end != packets_in_order.end() && window_end->first < time) {
908 bytes_in_window += window_end->second;
909 ++window_end;
910 }
911 while (window_begin != packets_in_order.end() &&
912 window_begin->first < time - config_.window_duration_) {
913 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
914 bytes_in_window -= window_begin->second;
915 ++window_begin;
916 }
917 float window_duration_in_seconds =
918 static_cast<float>(config_.window_duration_.us()) /
919 kNumMicrosecsPerSec;
920 float x = config_.GetCallTimeSec(time);
921 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
922 bitrate_series.points.emplace_back(x, y);
923 }
924 plot->AppendTimeSeries(std::move(bitrate_series));
925 }
926
927 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
928 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
929 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
930 float x = config_.GetCallTimeSec(loss_update.log_time());
931 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
932 loss_series.points.emplace_back(x, y);
933 }
934
935 TimeSeries link_capacity_lower_series("Link-capacity-lower",
936 LineStyle::kStep);
937 TimeSeries link_capacity_upper_series("Link-capacity-upper",
938 LineStyle::kStep);
939 for (auto& remote_estimate_event : parsed_log_.remote_estimate_events()) {
940 float x = config_.GetCallTimeSec(remote_estimate_event.log_time());
941 if (remote_estimate_event.link_capacity_lower.has_value()) {
942 float link_capacity_lower = static_cast<float>(
943 remote_estimate_event.link_capacity_lower.value().kbps());
944 link_capacity_lower_series.points.emplace_back(x, link_capacity_lower);
945 }
946 if (remote_estimate_event.link_capacity_upper.has_value()) {
947 float link_capacity_upper = static_cast<float>(
948 remote_estimate_event.link_capacity_upper.value().kbps());
949 link_capacity_upper_series.points.emplace_back(x, link_capacity_upper);
950 }
951 }
952
953 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
954 IntervalSeries overusing_series("Overusing", "#ff8e82",
955 IntervalSeries::kHorizontal);
956 IntervalSeries underusing_series("Underusing", "#5092fc",
957 IntervalSeries::kHorizontal);
958 IntervalSeries normal_series("Normal", "#c4ffc4",
959 IntervalSeries::kHorizontal);
960 IntervalSeries* last_series = &normal_series;
961 float last_detector_switch = 0.0;
962
963 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
964
965 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
966 float x = config_.GetCallTimeSec(delay_update.log_time());
967 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
968
969 if (last_detector_state != delay_update.detector_state) {
970 last_series->intervals.emplace_back(last_detector_switch, x);
971 last_detector_state = delay_update.detector_state;
972 last_detector_switch = x;
973
974 switch (delay_update.detector_state) {
975 case BandwidthUsage::kBwNormal:
976 last_series = &normal_series;
977 break;
978 case BandwidthUsage::kBwUnderusing:
979 last_series = &underusing_series;
980 break;
981 case BandwidthUsage::kBwOverusing:
982 last_series = &overusing_series;
983 break;
984 case BandwidthUsage::kLast:
985 RTC_DCHECK_NOTREACHED();
986 }
987 }
988
989 delay_series.points.emplace_back(x, y);
990 }
991
992 RTC_CHECK(last_series);
993 last_series->intervals.emplace_back(last_detector_switch,
994 config_.CallEndTimeSec());
995
996 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
997 PointStyle::kHighlight);
998 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
999 float x = config_.GetCallTimeSec(cluster.log_time());
1000 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
1001 created_series.points.emplace_back(x, y);
1002 }
1003
1004 TimeSeries result_series("Probing results.", LineStyle::kNone,
1005 PointStyle::kHighlight);
1006 for (auto& result : parsed_log_.bwe_probe_success_events()) {
1007 float x = config_.GetCallTimeSec(result.log_time());
1008 float y = static_cast<float>(result.bitrate_bps) / 1000;
1009 result_series.points.emplace_back(x, y);
1010 }
1011
1012 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1013 PointStyle::kHighlight);
1014 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
1015 float x = config_.GetCallTimeSec(failure.log_time());
1016 probe_failures_series.points.emplace_back(x, 0);
1017 }
1018
1019 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1020 bool previously_in_alr = false;
1021 Timestamp alr_start = Timestamp::Zero();
1022 for (auto& alr : parsed_log_.alr_state_events()) {
1023 float y = config_.GetCallTimeSec(alr.log_time());
1024 if (!previously_in_alr && alr.in_alr) {
1025 alr_start = alr.log_time();
1026 previously_in_alr = true;
1027 } else if (previously_in_alr && !alr.in_alr) {
1028 float x = config_.GetCallTimeSec(alr_start);
1029 alr_state.intervals.emplace_back(x, y);
1030 previously_in_alr = false;
1031 }
1032 }
1033
1034 if (previously_in_alr) {
1035 float x = config_.GetCallTimeSec(alr_start);
1036 float y = config_.GetCallTimeSec(config_.end_time_);
1037 alr_state.intervals.emplace_back(x, y);
1038 }
1039
1040 if (show_detector_state) {
1041 plot->AppendIntervalSeries(std::move(overusing_series));
1042 plot->AppendIntervalSeries(std::move(underusing_series));
1043 plot->AppendIntervalSeries(std::move(normal_series));
1044 }
1045
1046 if (show_alr_state) {
1047 plot->AppendIntervalSeries(std::move(alr_state));
1048 }
1049
1050 if (show_link_capacity) {
1051 plot->AppendTimeSeriesIfNotEmpty(std::move(link_capacity_lower_series));
1052 plot->AppendTimeSeriesIfNotEmpty(std::move(link_capacity_upper_series));
1053 }
1054
1055 plot->AppendTimeSeries(std::move(loss_series));
1056 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
1057 plot->AppendTimeSeries(std::move(delay_series));
1058 plot->AppendTimeSeries(std::move(created_series));
1059 plot->AppendTimeSeries(std::move(result_series));
1060
1061 // Overlay the incoming REMB over the outgoing bitrate.
1062 TimeSeries remb_series("Remb", LineStyle::kStep);
1063 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
1064 float x = config_.GetCallTimeSec(rtcp.log_time());
1065 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
1066 remb_series.points.emplace_back(x, y);
1067 }
1068 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1069
1070 if (!parsed_log_.generic_packets_sent().empty()) {
1071 {
1072 TimeSeries time_series("Outgoing generic total bitrate",
1073 LineStyle::kLine);
1074 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1075 return packet.packet_length() * 8.0 / 1000.0;
1076 };
1077 MovingAverage<LoggedGenericPacketSent, double>(
1078 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1079 &time_series);
1080 plot->AppendTimeSeries(std::move(time_series));
1081 }
1082
1083 {
1084 TimeSeries time_series("Outgoing generic payload bitrate",
1085 LineStyle::kLine);
1086 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1087 return packet.payload_length * 8.0 / 1000.0;
1088 };
1089 MovingAverage<LoggedGenericPacketSent, double>(
1090 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1091 &time_series);
1092 plot->AppendTimeSeries(std::move(time_series));
1093 }
1094 }
1095
1096 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1097 "Time (s)", kLeftMargin, kRightMargin);
1098 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1099 plot->SetTitle("Outgoing RTP bitrate");
1100 }
1101
1102 // For each SSRC, plot the bandwidth used by that stream.
CreateStreamBitrateGraph(PacketDirection direction,Plot * plot)1103 void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1104 Plot* plot) {
1105 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1106 // Filter on SSRC.
1107 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
1108 continue;
1109 }
1110
1111 TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
1112 LineStyle::kLine);
1113 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1114 return packet.total_length * 8.0 / 1000.0;
1115 };
1116 MovingAverage<LoggedRtpPacket, double>(
1117 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
1118 plot->AppendTimeSeries(std::move(time_series));
1119 }
1120
1121 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1122 "Time (s)", kLeftMargin, kRightMargin);
1123 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1124 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
1125 }
1126
1127 // Plot the bitrate allocation for each temporal and spatial layer.
1128 // Computed from RTCP XR target bitrate block, so the graph is only populated if
1129 // those are sent.
CreateBitrateAllocationGraph(PacketDirection direction,Plot * plot)1130 void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1131 Plot* plot) {
1132 std::map<LayerDescription, TimeSeries> time_series;
1133 const auto& xr_list = parsed_log_.extended_reports(direction);
1134 for (const auto& rtcp : xr_list) {
1135 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1136 rtcp.xr.target_bitrate();
1137 if (!target_bitrate.has_value())
1138 continue;
1139 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1140 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1141 bitrate_item.temporal_layer);
1142 auto time_series_it = time_series.find(layer);
1143 if (time_series_it == time_series.end()) {
1144 std::string layer_name = GetLayerName(layer);
1145 bool inserted;
1146 std::tie(time_series_it, inserted) = time_series.insert(
1147 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1148 RTC_DCHECK(inserted);
1149 }
1150 float x = config_.GetCallTimeSec(rtcp.log_time());
1151 float y = bitrate_item.target_bitrate_kbps;
1152 time_series_it->second.points.emplace_back(x, y);
1153 }
1154 }
1155 for (auto& layer : time_series) {
1156 plot->AppendTimeSeries(std::move(layer.second));
1157 }
1158 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1159 "Time (s)", kLeftMargin, kRightMargin);
1160 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1161 if (direction == kIncomingPacket)
1162 plot->SetTitle("Target bitrate per incoming layer");
1163 else
1164 plot->SetTitle("Target bitrate per outgoing layer");
1165 }
1166
CreateGoogCcSimulationGraph(Plot * plot)1167 void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1168 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1169 PointStyle::kHighlight);
1170 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1171 PointStyle::kHighlight);
1172 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1173 PointStyle::kHighlight);
1174 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1175 PointStyle::kHighlight);
1176
1177 LogBasedNetworkControllerSimulation simulation(
1178 std::make_unique<GoogCcNetworkControllerFactory>(),
1179 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1180 if (update.target_rate) {
1181 target_rates.points.emplace_back(
1182 config_.GetCallTimeSec(at_time),
1183 update.target_rate->target_rate.kbps<float>());
1184 }
1185 });
1186
1187 simulation.ProcessEventsInLog(parsed_log_);
1188 for (const auto& logged : parsed_log_.bwe_delay_updates())
1189 delay_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time()),
1190 logged.bitrate_bps / 1000);
1191 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1192 probe_results.points.emplace_back(config_.GetCallTimeSec(logged.log_time()),
1193 logged.bitrate_bps / 1000);
1194 for (const auto& logged : parsed_log_.bwe_loss_updates())
1195 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time()),
1196 logged.bitrate_bps / 1000);
1197
1198 plot->AppendTimeSeries(std::move(delay_based));
1199 plot->AppendTimeSeries(std::move(loss_based));
1200 plot->AppendTimeSeries(std::move(probe_results));
1201 plot->AppendTimeSeries(std::move(target_rates));
1202
1203 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1204 "Time (s)", kLeftMargin, kRightMargin);
1205 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1206 plot->SetTitle("Simulated BWE behavior");
1207 }
1208
CreateSendSideBweSimulationGraph(Plot * plot)1209 void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
1210 using RtpPacketType = LoggedRtpPacketOutgoing;
1211 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
1212
1213 // TODO(terelius): This could be provided by the parser.
1214 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1215 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1216 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1217 outgoing_rtp.insert(
1218 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
1219 }
1220
1221 const std::vector<TransportFeedbackType>& incoming_rtcp =
1222 parsed_log_.transport_feedbacks(kIncomingPacket);
1223
1224 SimulatedClock clock(0);
1225 BitrateObserver observer;
1226 RtcEventLogNull null_event_log;
1227 TransportFeedbackAdapter transport_feedback;
1228 auto factory = GoogCcNetworkControllerFactory();
1229 TimeDelta process_interval = factory.GetProcessInterval();
1230 // TODO(holmer): Log the call config and use that here instead.
1231 static const uint32_t kDefaultStartBitrateBps = 300000;
1232 NetworkControllerConfig cc_config;
1233 cc_config.constraints.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
1234 cc_config.constraints.starting_rate =
1235 DataRate::BitsPerSec(kDefaultStartBitrateBps);
1236 cc_config.event_log = &null_event_log;
1237 auto goog_cc = factory.Create(cc_config);
1238
1239 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1240 PointStyle::kHighlight);
1241 TimeSeries acked_time_series("Raw acked bitrate", LineStyle::kLine,
1242 PointStyle::kHighlight);
1243 TimeSeries robust_time_series("Robust throughput estimate", LineStyle::kLine,
1244 PointStyle::kHighlight);
1245 TimeSeries acked_estimate_time_series("Ackednowledged bitrate estimate",
1246 LineStyle::kLine,
1247 PointStyle::kHighlight);
1248
1249 auto rtp_iterator = outgoing_rtp.begin();
1250 auto rtcp_iterator = incoming_rtcp.begin();
1251
1252 auto NextRtpTime = [&]() {
1253 if (rtp_iterator != outgoing_rtp.end())
1254 return static_cast<int64_t>(rtp_iterator->first);
1255 return std::numeric_limits<int64_t>::max();
1256 };
1257
1258 auto NextRtcpTime = [&]() {
1259 if (rtcp_iterator != incoming_rtcp.end())
1260 return static_cast<int64_t>(rtcp_iterator->log_time_us());
1261 return std::numeric_limits<int64_t>::max();
1262 };
1263 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
1264
1265 auto NextProcessTime = [&]() {
1266 if (rtcp_iterator != incoming_rtcp.end() ||
1267 rtp_iterator != outgoing_rtp.end()) {
1268 return next_process_time_us_;
1269 }
1270 return std::numeric_limits<int64_t>::max();
1271 };
1272
1273 RateStatistics raw_acked_bitrate(750, 8000);
1274 test::ExplicitKeyValueConfig throughput_config(
1275 "WebRTC-Bwe-RobustThroughputEstimatorSettings/"
1276 "enabled:true,required_packets:10,"
1277 "window_packets:25,window_duration:1000ms,unacked_weight:1.0/");
1278 std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1279 robust_throughput_estimator(
1280 AcknowledgedBitrateEstimatorInterface::Create(&throughput_config));
1281 FieldTrialBasedConfig field_trial_config;
1282 std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1283 acknowledged_bitrate_estimator(
1284 AcknowledgedBitrateEstimatorInterface::Create(&field_trial_config));
1285 int64_t time_us =
1286 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1287 int64_t last_update_us = 0;
1288 while (time_us != std::numeric_limits<int64_t>::max()) {
1289 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1290 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1291 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1292 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1293 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1294 RtpPacketSendInfo packet_info;
1295 packet_info.media_ssrc = rtp_packet.rtp.header.ssrc;
1296 packet_info.transport_sequence_number =
1297 rtp_packet.rtp.header.extension.transportSequenceNumber;
1298 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
1299 packet_info.length = rtp_packet.rtp.total_length;
1300 if (IsRtxSsrc(parsed_log_, PacketDirection::kOutgoingPacket,
1301 rtp_packet.rtp.header.ssrc)) {
1302 // Don't set the optional media type as we don't know if it is
1303 // a retransmission, FEC or padding.
1304 } else if (IsVideoSsrc(parsed_log_, PacketDirection::kOutgoingPacket,
1305 rtp_packet.rtp.header.ssrc)) {
1306 packet_info.packet_type = RtpPacketMediaType::kVideo;
1307 } else if (IsAudioSsrc(parsed_log_, PacketDirection::kOutgoingPacket,
1308 rtp_packet.rtp.header.ssrc)) {
1309 packet_info.packet_type = RtpPacketMediaType::kAudio;
1310 }
1311 transport_feedback.AddPacket(
1312 packet_info,
1313 0u, // Per packet overhead bytes.
1314 Timestamp::Micros(rtp_packet.rtp.log_time_us()));
1315 }
1316 rtc::SentPacket sent_packet;
1317 sent_packet.send_time_ms = rtp_packet.rtp.log_time_ms();
1318 sent_packet.info.included_in_allocation = true;
1319 sent_packet.info.packet_size_bytes = rtp_packet.rtp.total_length;
1320 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1321 sent_packet.packet_id =
1322 rtp_packet.rtp.header.extension.transportSequenceNumber;
1323 sent_packet.info.included_in_feedback = true;
1324 }
1325 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1326 if (sent_msg)
1327 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1328 ++rtp_iterator;
1329 }
1330 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
1331 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
1332
1333 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
1334 rtcp_iterator->transport_feedback,
1335 Timestamp::Millis(clock.TimeInMilliseconds()));
1336 if (feedback_msg) {
1337 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
1338 std::vector<PacketResult> feedback =
1339 feedback_msg->SortedByReceiveTime();
1340 if (!feedback.empty()) {
1341 acknowledged_bitrate_estimator->IncomingPacketFeedbackVector(
1342 feedback);
1343 robust_throughput_estimator->IncomingPacketFeedbackVector(feedback);
1344 for (const PacketResult& packet : feedback) {
1345 raw_acked_bitrate.Update(packet.sent_packet.size.bytes(),
1346 packet.receive_time.ms());
1347 }
1348 absl::optional<uint32_t> raw_bitrate_bps =
1349 raw_acked_bitrate.Rate(feedback.back().receive_time.ms());
1350 float x = config_.GetCallTimeSec(clock.CurrentTime());
1351 if (raw_bitrate_bps) {
1352 float y = raw_bitrate_bps.value() / 1000;
1353 acked_time_series.points.emplace_back(x, y);
1354 }
1355 absl::optional<DataRate> robust_estimate =
1356 robust_throughput_estimator->bitrate();
1357 if (robust_estimate) {
1358 float y = robust_estimate.value().kbps();
1359 robust_time_series.points.emplace_back(x, y);
1360 }
1361 absl::optional<DataRate> acked_estimate =
1362 acknowledged_bitrate_estimator->bitrate();
1363 if (acked_estimate) {
1364 float y = acked_estimate.value().kbps();
1365 acked_estimate_time_series.points.emplace_back(x, y);
1366 }
1367 }
1368 }
1369 ++rtcp_iterator;
1370 }
1371 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1372 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
1373 ProcessInterval msg;
1374 msg.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
1375 observer.Update(goog_cc->OnProcessInterval(msg));
1376 next_process_time_us_ += process_interval.us();
1377 }
1378 if (observer.GetAndResetBitrateUpdated() ||
1379 time_us - last_update_us >= 1e6) {
1380 uint32_t y = observer.last_bitrate_bps() / 1000;
1381 float x = config_.GetCallTimeSec(clock.CurrentTime());
1382 time_series.points.emplace_back(x, y);
1383 last_update_us = time_us;
1384 }
1385 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1386 }
1387 // Add the data set to the plot.
1388 plot->AppendTimeSeries(std::move(time_series));
1389 plot->AppendTimeSeries(std::move(robust_time_series));
1390 plot->AppendTimeSeries(std::move(acked_time_series));
1391 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
1392
1393 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1394 "Time (s)", kLeftMargin, kRightMargin);
1395 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1396 plot->SetTitle("Simulated send-side BWE behavior");
1397 }
1398
CreateReceiveSideBweSimulationGraph(Plot * plot)1399 void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
1400 using RtpPacketType = LoggedRtpPacketIncoming;
1401 class RembInterceptor {
1402 public:
1403 void SendRemb(uint32_t bitrate_bps, std::vector<uint32_t> ssrcs) {
1404 last_bitrate_bps_ = bitrate_bps;
1405 bitrate_updated_ = true;
1406 }
1407 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1408 bool GetAndResetBitrateUpdated() {
1409 bool bitrate_updated = bitrate_updated_;
1410 bitrate_updated_ = false;
1411 return bitrate_updated;
1412 }
1413
1414 private:
1415 // We don't know the start bitrate, but assume that it is the default 300
1416 // kbps.
1417 uint32_t last_bitrate_bps_ = 300000;
1418 bool bitrate_updated_ = false;
1419 };
1420
1421 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
1422
1423 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1424 if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) {
1425 for (const auto& rtp_packet : stream.incoming_packets)
1426 incoming_rtp.insert(
1427 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
1428 }
1429 }
1430
1431 SimulatedClock clock(0);
1432 RembInterceptor remb_interceptor;
1433 ReceiveSideCongestionController rscc(
1434 &clock, [](auto...) {},
1435 absl::bind_front(&RembInterceptor::SendRemb, &remb_interceptor), nullptr);
1436 // TODO(holmer): Log the call config and use that here instead.
1437 // static const uint32_t kDefaultStartBitrateBps = 300000;
1438 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1439
1440 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1441 PointStyle::kHighlight);
1442 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
1443
1444 RateStatistics acked_bitrate(250, 8000);
1445 int64_t last_update_us = 0;
1446 for (const auto& kv : incoming_rtp) {
1447 const RtpPacketType& packet = *kv.second;
1448 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1449 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1450 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
1451 clock.TimeInMicroseconds());
1452 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
1453 acked_bitrate.Update(payload, arrival_time_ms);
1454 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
1455 if (bitrate_bps) {
1456 uint32_t y = *bitrate_bps / 1000;
1457 float x = config_.GetCallTimeSec(clock.CurrentTime());
1458 acked_time_series.points.emplace_back(x, y);
1459 }
1460 if (remb_interceptor.GetAndResetBitrateUpdated() ||
1461 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1462 uint32_t y = remb_interceptor.last_bitrate_bps() / 1000;
1463 float x = config_.GetCallTimeSec(clock.CurrentTime());
1464 time_series.points.emplace_back(x, y);
1465 last_update_us = clock.TimeInMicroseconds();
1466 }
1467 }
1468 // Add the data set to the plot.
1469 plot->AppendTimeSeries(std::move(time_series));
1470 plot->AppendTimeSeries(std::move(acked_time_series));
1471
1472 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1473 "Time (s)", kLeftMargin, kRightMargin);
1474 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1475 plot->SetTitle("Simulated receive-side BWE behavior");
1476 }
1477
CreateNetworkDelayFeedbackGraph(Plot * plot)1478 void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
1479 TimeSeries time_series("Network delay", LineStyle::kLine,
1480 PointStyle::kHighlight);
1481 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1482 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
1483
1484 std::vector<MatchedSendArrivalTimes> matched_rtp_rtcp =
1485 GetNetworkTrace(parsed_log_);
1486 absl::c_stable_sort(matched_rtp_rtcp, [](const MatchedSendArrivalTimes& a,
1487 const MatchedSendArrivalTimes& b) {
1488 return a.feedback_arrival_time_ms < b.feedback_arrival_time_ms ||
1489 (a.feedback_arrival_time_ms == b.feedback_arrival_time_ms &&
1490 a.arrival_time_ms < b.arrival_time_ms);
1491 });
1492 for (const auto& packet : matched_rtp_rtcp) {
1493 if (packet.arrival_time_ms == MatchedSendArrivalTimes::kNotReceived)
1494 continue;
1495 float x = config_.GetCallTimeSecFromMs(packet.feedback_arrival_time_ms);
1496 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1497 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1498 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1499 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
1500 time_series.points.emplace_back(x, y);
1501 }
1502
1503 // We assume that the base network delay (w/o queues) is equal to half
1504 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1505 // observed 1-ways delay and add half the minimum RTT.
1506 const int64_t estimated_clock_offset_ms =
1507 min_send_receive_diff_ms - min_rtt_ms / 2;
1508 for (TimeSeriesPoint& point : time_series.points)
1509 point.y -= estimated_clock_offset_ms;
1510
1511 // Add the data set to the plot.
1512 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1513
1514 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1515 "Time (s)", kLeftMargin, kRightMargin);
1516 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
1517 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
1518 }
1519
CreatePacerDelayGraph(Plot * plot)1520 void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
1521 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1522 const std::vector<LoggedRtpPacketOutgoing>& packets =
1523 stream.outgoing_packets;
1524
1525 if (IsRtxSsrc(parsed_log_, kOutgoingPacket, stream.ssrc)) {
1526 continue;
1527 }
1528
1529 if (packets.size() < 2) {
1530 RTC_LOG(LS_WARNING)
1531 << "Can't estimate a the RTP clock frequency or the "
1532 "pacer delay with less than 2 packets in the stream";
1533 continue;
1534 }
1535 int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
1536 absl::optional<uint32_t> estimated_frequency =
1537 EstimateRtpClockFrequency(packets, segment_end_us);
1538 if (!estimated_frequency)
1539 continue;
1540 if (IsVideoSsrc(parsed_log_, kOutgoingPacket, stream.ssrc) &&
1541 *estimated_frequency != 90000) {
1542 RTC_LOG(LS_WARNING)
1543 << "Video stream should use a 90 kHz clock but appears to use "
1544 << *estimated_frequency / 1000 << ". Discarding.";
1545 continue;
1546 }
1547
1548 TimeSeries pacer_delay_series(
1549 GetStreamName(parsed_log_, kOutgoingPacket, stream.ssrc) + "(" +
1550 std::to_string(*estimated_frequency / 1000) + " kHz)",
1551 LineStyle::kLine, PointStyle::kHighlight);
1552 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1553 uint64_t first_capture_timestamp =
1554 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1555 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1556 for (const auto& packet : packets) {
1557 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
1558 packet.rtp.header.timestamp)) -
1559 first_capture_timestamp) /
1560 *estimated_frequency * 1000;
1561 double send_time_ms =
1562 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1563 1000;
1564 float x = config_.GetCallTimeSec(packet.rtp.log_time());
1565 float y = send_time_ms - capture_time_ms;
1566 pacer_delay_series.points.emplace_back(x, y);
1567 }
1568 plot->AppendTimeSeries(std::move(pacer_delay_series));
1569 }
1570
1571 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1572 "Time (s)", kLeftMargin, kRightMargin);
1573 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1574 plot->SetTitle(
1575 "Delay from capture to send time. (First packet normalized to 0.)");
1576 }
1577
CreateTimestampGraph(PacketDirection direction,Plot * plot)1578 void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1579 Plot* plot) {
1580 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1581 TimeSeries rtp_timestamps(
1582 GetStreamName(parsed_log_, direction, stream.ssrc) + " capture-time",
1583 LineStyle::kLine, PointStyle::kHighlight);
1584 for (const auto& packet : stream.packet_view) {
1585 float x = config_.GetCallTimeSec(packet.log_time());
1586 float y = packet.header.timestamp;
1587 rtp_timestamps.points.emplace_back(x, y);
1588 }
1589 plot->AppendTimeSeries(std::move(rtp_timestamps));
1590
1591 TimeSeries rtcp_timestamps(
1592 GetStreamName(parsed_log_, direction, stream.ssrc) +
1593 " rtcp capture-time",
1594 LineStyle::kLine, PointStyle::kHighlight);
1595 // TODO(terelius): Why only sender reports?
1596 const auto& sender_reports = parsed_log_.sender_reports(direction);
1597 for (const auto& rtcp : sender_reports) {
1598 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1599 continue;
1600 float x = config_.GetCallTimeSec(rtcp.log_time());
1601 float y = rtcp.sr.rtp_timestamp();
1602 rtcp_timestamps.points.emplace_back(x, y);
1603 }
1604 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
1605 }
1606
1607 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1608 "Time (s)", kLeftMargin, kRightMargin);
1609 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1610 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
1611 }
1612
CreateSenderAndReceiverReportPlot(PacketDirection direction,rtc::FunctionView<float (const rtcp::ReportBlock &)> fy,std::string title,std::string yaxis_label,Plot * plot)1613 void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1614 PacketDirection direction,
1615 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1616 std::string title,
1617 std::string yaxis_label,
1618 Plot* plot) {
1619 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1620 const auto& sender_reports = parsed_log_.sender_reports(direction);
1621 for (const auto& rtcp : sender_reports) {
1622 float x = config_.GetCallTimeSec(rtcp.log_time());
1623 uint32_t ssrc = rtcp.sr.sender_ssrc();
1624 for (const auto& block : rtcp.sr.report_blocks()) {
1625 float y = fy(block);
1626 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1627 bool inserted;
1628 if (sr_report_it == sr_reports_by_ssrc.end()) {
1629 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1630 ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) +
1631 " Sender Reports",
1632 LineStyle::kLine, PointStyle::kHighlight));
1633 }
1634 sr_report_it->second.points.emplace_back(x, y);
1635 }
1636 }
1637 for (auto& kv : sr_reports_by_ssrc) {
1638 plot->AppendTimeSeries(std::move(kv.second));
1639 }
1640
1641 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1642 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1643 for (const auto& rtcp : receiver_reports) {
1644 float x = config_.GetCallTimeSec(rtcp.log_time());
1645 uint32_t ssrc = rtcp.rr.sender_ssrc();
1646 for (const auto& block : rtcp.rr.report_blocks()) {
1647 float y = fy(block);
1648 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1649 bool inserted;
1650 if (rr_report_it == rr_reports_by_ssrc.end()) {
1651 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1652 ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) +
1653 " Receiver Reports",
1654 LineStyle::kLine, PointStyle::kHighlight));
1655 }
1656 rr_report_it->second.points.emplace_back(x, y);
1657 }
1658 }
1659 for (auto& kv : rr_reports_by_ssrc) {
1660 plot->AppendTimeSeries(std::move(kv.second));
1661 }
1662
1663 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1664 "Time (s)", kLeftMargin, kRightMargin);
1665 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1666 plot->SetTitle(title);
1667 }
1668
CreateIceCandidatePairConfigGraph(Plot * plot)1669 void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1670 std::map<uint32_t, TimeSeries> configs_by_cp_id;
1671 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
1672 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1673 configs_by_cp_id.end()) {
1674 const std::string candidate_pair_desc =
1675 GetCandidatePairLogDescriptionAsString(config);
1676 configs_by_cp_id[config.candidate_pair_id] =
1677 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1678 candidate_pair_desc,
1679 LineStyle::kNone, PointStyle::kHighlight);
1680 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1681 candidate_pair_desc;
1682 }
1683 float x = config_.GetCallTimeSec(config.log_time());
1684 float y = static_cast<float>(config.type);
1685 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1686 }
1687
1688 // TODO(qingsi): There can be a large number of candidate pairs generated by
1689 // certain calls and the frontend cannot render the chart in this case due to
1690 // the failure of generating a palette with the same number of colors.
1691 for (auto& kv : configs_by_cp_id) {
1692 plot->AppendTimeSeries(std::move(kv.second));
1693 }
1694
1695 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1696 "Time (s)", kLeftMargin, kRightMargin);
1697 plot->SetSuggestedYAxis(0, 3, "Config Type", kBottomMargin, kTopMargin);
1698 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1699 plot->SetYAxisTickLabels(
1700 {{static_cast<float>(IceCandidatePairConfigType::kAdded), "ADDED"},
1701 {static_cast<float>(IceCandidatePairConfigType::kUpdated), "UPDATED"},
1702 {static_cast<float>(IceCandidatePairConfigType::kDestroyed),
1703 "DESTROYED"},
1704 {static_cast<float>(IceCandidatePairConfigType::kSelected),
1705 "SELECTED"}});
1706 }
1707
GetCandidatePairLogDescriptionFromId(uint32_t candidate_pair_id)1708 std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1709 uint32_t candidate_pair_id) {
1710 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1711 candidate_pair_desc_by_id_.end()) {
1712 return candidate_pair_desc_by_id_[candidate_pair_id];
1713 }
1714 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
1715 // TODO(qingsi): Add the handling of the "Updated" config event after the
1716 // visualization of property change for candidate pairs is introduced.
1717 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1718 candidate_pair_desc_by_id_.end()) {
1719 const std::string candidate_pair_desc =
1720 GetCandidatePairLogDescriptionAsString(config);
1721 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1722 candidate_pair_desc;
1723 }
1724 }
1725 return candidate_pair_desc_by_id_[candidate_pair_id];
1726 }
1727
CreateIceConnectivityCheckGraph(Plot * plot)1728 void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1729 constexpr int kEventTypeOffset =
1730 static_cast<int>(IceCandidatePairConfigType::kNumValues);
1731 std::map<uint32_t, TimeSeries> checks_by_cp_id;
1732 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
1733 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1734 checks_by_cp_id.end()) {
1735 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
1736 "[" + std::to_string(event.candidate_pair_id) + "]" +
1737 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
1738 LineStyle::kNone, PointStyle::kHighlight);
1739 }
1740 float x = config_.GetCallTimeSec(event.log_time());
1741 float y = static_cast<float>(event.type) + kEventTypeOffset;
1742 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1743 }
1744
1745 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1746 for (auto& kv : checks_by_cp_id) {
1747 plot->AppendTimeSeries(std::move(kv.second));
1748 }
1749
1750 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1751 "Time (s)", kLeftMargin, kRightMargin);
1752 plot->SetSuggestedYAxis(0, 4, "Connectivity State", kBottomMargin,
1753 kTopMargin);
1754 plot->SetTitle("[IceEventLog] ICE connectivity checks");
1755
1756 plot->SetYAxisTickLabels(
1757 {{static_cast<float>(IceCandidatePairEventType::kCheckSent) +
1758 kEventTypeOffset,
1759 "CHECK SENT"},
1760 {static_cast<float>(IceCandidatePairEventType::kCheckReceived) +
1761 kEventTypeOffset,
1762 "CHECK RECEIVED"},
1763 {static_cast<float>(IceCandidatePairEventType::kCheckResponseSent) +
1764 kEventTypeOffset,
1765 "RESPONSE SENT"},
1766 {static_cast<float>(IceCandidatePairEventType::kCheckResponseReceived) +
1767 kEventTypeOffset,
1768 "RESPONSE RECEIVED"}});
1769 }
1770
CreateDtlsTransportStateGraph(Plot * plot)1771 void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
1772 TimeSeries states("DTLS Transport State", LineStyle::kNone,
1773 PointStyle::kHighlight);
1774 for (const auto& event : parsed_log_.dtls_transport_states()) {
1775 float x = config_.GetCallTimeSec(event.log_time());
1776 float y = static_cast<float>(event.dtls_transport_state);
1777 states.points.emplace_back(x, y);
1778 }
1779 plot->AppendTimeSeries(std::move(states));
1780 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1781 "Time (s)", kLeftMargin, kRightMargin);
1782 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
1783 "Transport State", kBottomMargin, kTopMargin);
1784 plot->SetTitle("DTLS Transport State");
1785 plot->SetYAxisTickLabels(
1786 {{static_cast<float>(DtlsTransportState::kNew), "NEW"},
1787 {static_cast<float>(DtlsTransportState::kConnecting), "CONNECTING"},
1788 {static_cast<float>(DtlsTransportState::kConnected), "CONNECTED"},
1789 {static_cast<float>(DtlsTransportState::kClosed), "CLOSED"},
1790 {static_cast<float>(DtlsTransportState::kFailed), "FAILED"}});
1791 }
1792
CreateDtlsWritableStateGraph(Plot * plot)1793 void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
1794 TimeSeries writable("DTLS Writable", LineStyle::kNone,
1795 PointStyle::kHighlight);
1796 for (const auto& event : parsed_log_.dtls_writable_states()) {
1797 float x = config_.GetCallTimeSec(event.log_time());
1798 float y = static_cast<float>(event.writable);
1799 writable.points.emplace_back(x, y);
1800 }
1801 plot->AppendTimeSeries(std::move(writable));
1802 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1803 "Time (s)", kLeftMargin, kRightMargin);
1804 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
1805 plot->SetTitle("DTLS Writable State");
1806 }
1807
1808 } // namespace webrtc
1809