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