blob: 8ca108e48f71889fad55b9c6a8dce6b175ca3930 [file] [log] [blame]
terelius54ce6802016-07-13 06:44:41 -07001/*
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
Mirko Bonadei575998c2019-07-25 13:57:41 +020011#include "rtc_tools/rtc_event_log_visualizer/analyzer.h"
terelius54ce6802016-07-13 06:44:41 -070012
13#include <algorithm>
Oleh Prypin6581f212017-11-16 00:17:05 +010014#include <cmath>
terelius54ce6802016-07-13 06:44:41 -070015#include <limits>
16#include <map>
Mirko Bonadei317a1f02019-09-17 17:06:18 +020017#include <memory>
terelius54ce6802016-07-13 06:44:41 -070018#include <string>
19#include <utility>
20
Björn Tereliusc69c1bb2019-10-11 15:06:58 +020021#include "absl/algorithm/container.h"
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +010022#include "absl/strings/string_view.h"
Artem Titov741daaf2019-03-21 14:37:36 +010023#include "api/function_view.h"
Sebastian Jansson95edb032019-01-17 16:24:12 +010024#include "api/transport/field_trial_based_config.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020025#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020026#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"
Kristoffer Erlandssona2ce4232020-04-01 14:33:30 +020031#include "logging/rtc_event_log/rtc_event_processor.h"
Elad Alon99a81b62017-09-21 10:25:29 +020032#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020033#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020034#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
35#include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020036#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020037#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020038#include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
Erik Språnge7942432019-06-12 13:30:02 +020039#include "modules/pacing/paced_sender.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010040#include "modules/pacing/packet_router.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020041#include "modules/remote_bitrate_estimator/include/bwe_defines.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020042#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020043#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020044#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"
Tomas Gunnarssonf25761d2020-06-03 22:55:33 +020050#include "modules/rtp_rtcp/source/rtp_rtcp_interface.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020051#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"
Bjorn Terelius0295a962017-10-25 17:42:41 +020055#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020056#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020057#include "rtc_base/strings/string_builder.h"
Mirko Bonadei575998c2019-07-25 13:57:41 +020058#include "rtc_tools/rtc_event_log_visualizer/log_simulation.h"
terelius54ce6802016-07-13 06:44:41 -070059
Bjorn Terelius6984ad22017-10-24 12:19:45 +020060#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
61#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
62#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
63
tereliusdc35dcd2016-08-01 12:03:27 -070064namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070065
terelius54ce6802016-07-13 06:44:41 -070066namespace {
67
68std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020069 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070070 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020071 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070072}
73
74// Checks whether an SSRC is contained in the list of desired SSRCs.
75// Note that an empty SSRC list matches every SSRC.
76bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
Mirko Bonadei1f173152019-07-25 15:28:14 +020077 if (desired_ssrc.empty())
terelius54ce6802016-07-13 06:44:41 -070078 return true;
79 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
80 desired_ssrc.end();
81}
82
83double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
84 // The timestamp is a fixed point representation with 6 bits for seconds
85 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080086 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
87 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070088 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080089 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -070090 return abs_send_time * kTimestampToMicroSec;
91}
92
93// Computes the difference |later| - |earlier| where |later| and |earlier|
94// are counters that wrap at |modulus|. The difference is chosen to have the
95// least absolute value. For example if |modulus| is 8, then the difference will
96// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
97// be in [-4, 4].
98int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
99 RTC_DCHECK_LE(1, modulus);
100 RTC_DCHECK_LT(later, modulus);
101 RTC_DCHECK_LT(earlier, modulus);
102 int64_t difference =
103 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
104 int64_t max_difference = modulus / 2;
105 int64_t min_difference = max_difference - modulus + 1;
106 if (difference > max_difference) {
107 difference -= modulus;
108 }
109 if (difference < min_difference) {
110 difference += modulus;
111 }
terelius6addf492016-08-23 17:34:07 -0700112 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100113 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
114 << " expected to be in the range ("
115 << min_difference / 2 << "," << max_difference / 2
116 << ") but is " << difference
117 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700118 }
terelius54ce6802016-07-13 06:44:41 -0700119 return difference;
120}
121
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200122// This is much more reliable for outgoing streams than for incoming streams.
123template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200124absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200125 const RtpPacketContainer& packets,
126 int64_t end_time_us) {
127 RTC_CHECK(packets.size() >= 2);
128 SeqNumUnwrapper<uint32_t> unwrapper;
Philip Eliasson1f850a62019-03-19 12:15:00 +0000129 int64_t first_rtp_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200130 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
131 int64_t first_log_timestamp = packets[0].log_time_us();
Philip Eliasson1f850a62019-03-19 12:15:00 +0000132 int64_t last_rtp_timestamp = first_rtp_timestamp;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200133 int64_t last_log_timestamp = first_log_timestamp;
134 for (size_t i = 1; i < packets.size(); i++) {
135 if (packets[i].log_time_us() > end_time_us)
136 break;
137 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
138 last_log_timestamp = packets[i].log_time_us();
139 }
140 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
141 RTC_LOG(LS_WARNING)
142 << "Failed to estimate RTP clock frequency: Stream too short. ("
143 << packets.size() << " packets, "
144 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200145 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200146 }
147 double duration =
148 static_cast<double>(last_log_timestamp - first_log_timestamp) /
149 kNumMicrosecsPerSec;
150 double estimated_frequency =
151 (last_rtp_timestamp - first_rtp_timestamp) / duration;
152 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
philipel3fa49382019-08-20 15:59:57 +0200153 if (std::fabs(estimated_frequency - f) < 0.15 * f) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200154 return f;
155 }
156 }
157 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
158 << estimated_frequency
philipel3fa49382019-08-20 15:59:57 +0200159 << " not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200160 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700161}
162
Danil Chapovalov431abd92018-06-18 12:54:17 +0200163absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100164 const LoggedRtpPacketIncoming& old_packet,
165 const LoggedRtpPacketIncoming& new_packet) {
166 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
167 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700168 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100169 new_packet.rtp.header.extension.absoluteSendTime,
170 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200171 int64_t recv_time_diff =
172 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700173 double delay_change_us =
174 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100175 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700176 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200177 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700178 }
179}
180
Danil Chapovalov431abd92018-06-18 12:54:17 +0200181absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100182 const LoggedRtpPacketIncoming& old_packet,
183 const LoggedRtpPacketIncoming& new_packet,
184 const double sample_rate) {
185 int64_t send_time_diff =
186 WrappingDifference(new_packet.rtp.header.timestamp,
187 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200188 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700189
terelius53dc23c2017-03-13 05:24:05 -0700190 double delay_change =
191 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100192 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700193 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100194 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100195 RTC_LOG(LS_WARNING) << "Old capture time "
196 << old_packet.rtp.header.timestamp << ", received time "
197 << old_packet.log_time_us();
198 RTC_LOG(LS_WARNING) << "New capture time "
199 << new_packet.rtp.header.timestamp << ", received time "
200 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100201 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800202 << static_cast<double>(recv_time_diff) /
203 kNumMicrosecsPerSec
204 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100205 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100206 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100207 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700208 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100209 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700210}
211
terelius6addf492016-08-23 17:34:07 -0700212
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100213template <typename T>
214TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
215 AnalyzerConfig config,
216 std::string rtcp_name,
217 int category_id) {
218 TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
219 for (const auto& rtcp : rtcp_list) {
220 float x = config.GetCallTimeSec(rtcp.log_time_us());
221 float y = category_id;
222 time_series.points.emplace_back(x, y);
223 }
224 return time_series;
225}
226
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800227const char kUnknownEnumValue[] = "unknown";
228
229const char kIceCandidateTypeLocal[] = "local";
230const char kIceCandidateTypeStun[] = "stun";
231const char kIceCandidateTypePrflx[] = "prflx";
232const char kIceCandidateTypeRelay[] = "relay";
233
234const char kProtocolUdp[] = "udp";
235const char kProtocolTcp[] = "tcp";
236const char kProtocolSsltcp[] = "ssltcp";
237const char kProtocolTls[] = "tls";
238
239const char kAddressFamilyIpv4[] = "ipv4";
240const char kAddressFamilyIpv6[] = "ipv6";
241
242const char kNetworkTypeEthernet[] = "ethernet";
243const char kNetworkTypeLoopback[] = "loopback";
244const char kNetworkTypeWifi[] = "wifi";
245const char kNetworkTypeVpn[] = "vpn";
246const char kNetworkTypeCellular[] = "cellular";
247
248std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
249 switch (type) {
250 case webrtc::IceCandidateType::kLocal:
251 return kIceCandidateTypeLocal;
252 case webrtc::IceCandidateType::kStun:
253 return kIceCandidateTypeStun;
254 case webrtc::IceCandidateType::kPrflx:
255 return kIceCandidateTypePrflx;
256 case webrtc::IceCandidateType::kRelay:
257 return kIceCandidateTypeRelay;
258 default:
259 return kUnknownEnumValue;
260 }
261}
262
263std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
264 switch (protocol) {
265 case webrtc::IceCandidatePairProtocol::kUdp:
266 return kProtocolUdp;
267 case webrtc::IceCandidatePairProtocol::kTcp:
268 return kProtocolTcp;
269 case webrtc::IceCandidatePairProtocol::kSsltcp:
270 return kProtocolSsltcp;
271 case webrtc::IceCandidatePairProtocol::kTls:
272 return kProtocolTls;
273 default:
274 return kUnknownEnumValue;
275 }
276}
277
278std::string GetAddressFamilyAsString(
279 webrtc::IceCandidatePairAddressFamily family) {
280 switch (family) {
281 case webrtc::IceCandidatePairAddressFamily::kIpv4:
282 return kAddressFamilyIpv4;
283 case webrtc::IceCandidatePairAddressFamily::kIpv6:
284 return kAddressFamilyIpv6;
285 default:
286 return kUnknownEnumValue;
287 }
288}
289
290std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
291 switch (type) {
292 case webrtc::IceCandidateNetworkType::kEthernet:
293 return kNetworkTypeEthernet;
294 case webrtc::IceCandidateNetworkType::kLoopback:
295 return kNetworkTypeLoopback;
296 case webrtc::IceCandidateNetworkType::kWifi:
297 return kNetworkTypeWifi;
298 case webrtc::IceCandidateNetworkType::kVpn:
299 return kNetworkTypeVpn;
300 case webrtc::IceCandidateNetworkType::kCellular:
301 return kNetworkTypeCellular;
302 default:
303 return kUnknownEnumValue;
304 }
305}
306
307std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200308 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800309 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
310 // represents a pair of a local server-reflexive candidate on a WiFi network
311 // and a remote relay candidate using TCP as the relay protocol on a cell
312 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200313 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800314 std::string local_candidate_type =
315 GetIceCandidateTypeAsString(config.local_candidate_type);
316 std::string remote_candidate_type =
317 GetIceCandidateTypeAsString(config.remote_candidate_type);
318 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
319 local_candidate_type +=
320 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
321 }
322 ss << local_candidate_type << ":"
323 << GetNetworkTypeAsString(config.local_network_type) << ":"
324 << GetAddressFamilyAsString(config.local_address_family) << "->"
325 << remote_candidate_type << ":"
326 << GetAddressFamilyAsString(config.remote_address_family) << "@"
327 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200328 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800329}
330
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200331std::string GetDirectionAsString(PacketDirection direction) {
332 if (direction == kIncomingPacket) {
333 return "Incoming";
334 } else {
335 return "Outgoing";
336 }
337}
338
339std::string GetDirectionAsShortString(PacketDirection direction) {
340 if (direction == kIncomingPacket) {
341 return "In";
342 } else {
343 return "Out";
344 }
345}
346
terelius54ce6802016-07-13 06:44:41 -0700347} // namespace
348
Sebastian Janssonb290a6d2019-01-03 14:46:23 +0100349EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200350 bool normalize_time)
Bjorn Terelius068fc352019-02-13 22:38:25 +0100351 : parsed_log_(log) {
352 config_.window_duration_ = 250000;
353 config_.step_ = 10000;
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_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200358 RTC_LOG(LS_WARNING) << "No useful events in the log.";
Bjorn Terelius068fc352019-02-13 22:38:25 +0100359 config_.begin_time_ = config_.end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000360 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200361
Björn Terelius0d1b28c2020-05-27 20:25:06 +0200362 RTC_LOG(LS_INFO) << "Log is "
363 << (parsed_log_.last_timestamp() -
364 parsed_log_.first_timestamp()) /
365 1000000
366 << " seconds long.";
Bjorn Terelius48b82792020-05-19 10:57:24 +0200367}
368
369EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
370 const AnalyzerConfig& config)
371 : parsed_log_(log), config_(config) {
Björn Terelius0d1b28c2020-05-27 20:25:06 +0200372 RTC_LOG(LS_INFO) << "Log is "
373 << (parsed_log_.last_timestamp() -
374 parsed_log_.first_timestamp()) /
375 1000000
376 << " seconds long.";
terelius54ce6802016-07-13 06:44:41 -0700377}
378
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200379class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200380 public:
381 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
382
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200383 void Update(NetworkControlUpdate update) {
384 if (update.target_rate) {
385 last_bitrate_bps_ = update.target_rate->target_rate.bps();
386 bitrate_updated_ = true;
387 }
Stefan Holmer13181032016-07-29 14:48:54 +0200388 }
389
390 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
391 uint32_t bitrate) override {}
392
393 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
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
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200405void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700406 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200407 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
408 // Filter on SSRC.
409 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700410 continue;
terelius54ce6802016-07-13 06:44:41 -0700411 }
terelius54ce6802016-07-13 06:44:41 -0700412
Bjorn Terelius48b82792020-05-19 10:57:24 +0200413 TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200414 LineStyle::kBar);
415 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200416 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200417 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200418 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100419 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200420 };
421 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
422 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700423 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700424 }
425
Bjorn Terelius068fc352019-02-13 22:38:25 +0100426 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
427 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700428 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
429 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200430 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700431}
432
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100433void 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->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
452 "Time (s)", kLeftMargin, kRightMargin);
453 plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
454 plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
Bjorn Tereliusf640b872019-07-24 15:46:39 +0200455 plot->SetYAxisTickLabels({{1, "TWCC"},
456 {2, "RR"},
457 {3, "SR"},
458 {4, "XR"},
459 {5, "NACK"},
460 {6, "REMB"},
461 {7, "FIR"},
462 {8, "PLI"}});
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100463}
464
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200465template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700466void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700467 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200468 const IterableType& packets,
469 const std::string& label) {
470 TimeSeries time_series(label, LineStyle::kStep);
471 for (size_t i = 0; i < packets.size(); i++) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100472 float x = config_.GetCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200473 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700474 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200475 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700476}
477
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200478void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
479 Plot* plot) {
480 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
481 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
482 continue;
Bjorn Terelius48b82792020-05-19 10:57:24 +0200483 std::string label = std::string("RTP ") +
484 GetStreamName(parsed_log_, direction, stream.ssrc);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200485 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
486 }
487 std::string label =
488 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
489 if (direction == kIncomingPacket) {
490 CreateAccumulatedPacketsTimeSeries(
491 plot, parsed_log_.incoming_rtcp_packets(), label);
492 } else {
493 CreateAccumulatedPacketsTimeSeries(
494 plot, parsed_log_.outgoing_rtcp_packets(), label);
495 }
philipelccd74892016-09-05 02:46:25 -0700496
Bjorn Terelius068fc352019-02-13 22:38:25 +0100497 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
498 "Time (s)", kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700499 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200500 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
501 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700502}
503
Kristoffer Erlandsson283c1062020-03-30 13:01:37 +0200504void EventLogAnalyzer::CreatePacketRateGraph(PacketDirection direction,
505 Plot* plot) {
506 auto CountPackets = [](auto packet) { return 1.0; };
507 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
508 // Filter on SSRC.
509 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
510 continue;
511 }
512 TimeSeries time_series(
Bjorn Terelius48b82792020-05-19 10:57:24 +0200513 std::string("RTP ") +
514 GetStreamName(parsed_log_, direction, stream.ssrc),
Kristoffer Erlandsson283c1062020-03-30 13:01:37 +0200515 LineStyle::kLine);
516 MovingAverage<LoggedRtpPacket, double>(CountPackets, stream.packet_view,
517 config_, &time_series);
518 plot->AppendTimeSeries(std::move(time_series));
519 }
520 TimeSeries time_series(
521 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")",
522 LineStyle::kLine);
523 if (direction == kIncomingPacket) {
524 MovingAverage<LoggedRtcpPacketIncoming, double>(
525 CountPackets, parsed_log_.incoming_rtcp_packets(), config_,
526 &time_series);
527 } else {
528 MovingAverage<LoggedRtcpPacketOutgoing, double>(
529 CountPackets, parsed_log_.outgoing_rtcp_packets(), config_,
530 &time_series);
531 }
532 plot->AppendTimeSeries(std::move(time_series));
533
534 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
535 "Time (s)", kLeftMargin, kRightMargin);
536 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
537 kTopMargin);
538 plot->SetTitle("Rate of " + GetDirectionAsString(direction) +
539 " RTP/RTCP packets");
540}
541
Kristoffer Erlandssona2ce4232020-04-01 14:33:30 +0200542void EventLogAnalyzer::CreateTotalPacketRateGraph(PacketDirection direction,
543 Plot* plot) {
544 // Contains a log timestamp to enable counting logged events of different
545 // types using MovingAverage().
546 class LogTime {
547 public:
548 explicit LogTime(int64_t log_time_us) : log_time_us_(log_time_us) {}
549
550 int64_t log_time_us() const { return log_time_us_; }
551
552 private:
553 int64_t log_time_us_;
554 };
555
556 std::vector<LogTime> packet_times;
557 auto handle_rtp = [&](const LoggedRtpPacket& packet) {
558 packet_times.emplace_back(packet.log_time_us());
559 };
560 RtcEventProcessor process;
561 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
562 process.AddEvents(stream.packet_view, handle_rtp);
563 }
564 if (direction == kIncomingPacket) {
565 auto handle_incoming_rtcp = [&](const LoggedRtcpPacketIncoming& packet) {
566 packet_times.emplace_back(packet.log_time_us());
567 };
568 process.AddEvents(parsed_log_.incoming_rtcp_packets(),
569 handle_incoming_rtcp);
570 } else {
571 auto handle_outgoing_rtcp = [&](const LoggedRtcpPacketOutgoing& packet) {
572 packet_times.emplace_back(packet.log_time_us());
573 };
574 process.AddEvents(parsed_log_.outgoing_rtcp_packets(),
575 handle_outgoing_rtcp);
576 }
577 process.ProcessEventsInOrder();
578 TimeSeries time_series(std::string("Total ") + "(" +
579 GetDirectionAsShortString(direction) + ") packets",
580 LineStyle::kLine);
581 MovingAverage<LogTime, uint64_t>([](auto packet) { return 1; }, packet_times,
582 config_, &time_series);
583 plot->AppendTimeSeries(std::move(time_series));
584
585 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
586 "Time (s)", kLeftMargin, kRightMargin);
587 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
588 kTopMargin);
589 plot->SetTitle("Rate of all " + GetDirectionAsString(direction) +
590 " RTP/RTCP packets");
591}
592
terelius54ce6802016-07-13 06:44:41 -0700593// For each SSRC, plot the time between the consecutive playouts.
594void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200595 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
596 uint32_t ssrc = playout_stream.first;
597 if (!MatchingSsrc(ssrc, desired_ssrc_))
598 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200599 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200600 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200601 for (const auto& playout_event : playout_stream.second) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100602 float x = config_.GetCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200603 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200604 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200605 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200606 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200607 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700608 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200609 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700610 }
611
Bjorn Terelius068fc352019-02-13 22:38:25 +0100612 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
613 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700614 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
615 kTopMargin);
616 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700617}
618
ivocaac9d6f2016-09-22 07:01:47 -0700619// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200620void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
621 Plot* plot) {
622 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
Bjorn Terelius48b82792020-05-19 10:57:24 +0200623 if (!IsAudioSsrc(parsed_log_, direction, stream.ssrc))
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200624 continue;
Bjorn Terelius48b82792020-05-19 10:57:24 +0200625 TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200626 LineStyle::kLine);
627 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700628 if (packet.header.extension.hasAudioLevel) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100629 float x = config_.GetCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700630 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
631 // Here we convert it to dBov.
632 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200633 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700634 }
635 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200636 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700637 }
638
Bjorn Terelius068fc352019-02-13 22:38:25 +0100639 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
640 "Time (s)", kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200641 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200642 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700643}
644
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100645// For each SSRC, plot the sequence number difference between consecutive
646// incoming packets.
terelius54ce6802016-07-13 06:44:41 -0700647void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200648 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
649 // Filter on SSRC.
650 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700651 continue;
terelius54ce6802016-07-13 06:44:41 -0700652 }
terelius54ce6802016-07-13 06:44:41 -0700653
Bjorn Terelius48b82792020-05-19 10:57:24 +0200654 TimeSeries time_series(
655 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc),
656 LineStyle::kBar);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200657 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
658 const LoggedRtpPacketIncoming& new_packet) {
659 int64_t diff =
660 WrappingDifference(new_packet.rtp.header.sequenceNumber,
661 old_packet.rtp.header.sequenceNumber, 1ul << 16);
662 return diff;
663 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200664 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100665 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200666 };
667 ProcessPairs<LoggedRtpPacketIncoming, float>(
668 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
669 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700670 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700671 }
672
Bjorn Terelius068fc352019-02-13 22:38:25 +0100673 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
674 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700675 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
676 kTopMargin);
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100677 plot->SetTitle("Incoming sequence number delta");
terelius54ce6802016-07-13 06:44:41 -0700678}
679
Stefan Holmer99f8e082016-09-09 13:37:50 +0200680void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200681 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
682 const std::vector<LoggedRtpPacketIncoming>& packets =
683 stream.incoming_packets;
684 // Filter on SSRC.
Mirko Bonadei1f173152019-07-25 15:28:14 +0200685 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.empty()) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200686 continue;
687 }
688
Bjorn Terelius48b82792020-05-19 10:57:24 +0200689 TimeSeries time_series(
690 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc),
691 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200692 // TODO(terelius): Should the window and step size be read from the class
693 // instead?
694 const int64_t kWindowUs = 1000000;
695 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100696 SeqNumUnwrapper<uint16_t> unwrapper_;
697 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800698 size_t window_index_begin = 0;
699 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200700 uint64_t highest_seq_number =
701 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
702 uint64_t highest_prior_seq_number =
703 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800704
Bjorn Terelius068fc352019-02-13 22:38:25 +0100705 for (int64_t t = config_.begin_time_; t < config_.end_time_ + kStep;
706 t += kStep) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200707 while (window_index_end < packets.size() &&
708 packets[window_index_end].rtp.log_time_us() < t) {
709 uint64_t sequence_number = unwrapper_.Unwrap(
710 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800711 highest_seq_number = std::max(highest_seq_number, sequence_number);
712 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200713 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200714 while (window_index_begin < packets.size() &&
715 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
716 uint64_t sequence_number = prior_unwrapper_.Unwrap(
717 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800718 highest_prior_seq_number =
719 std::max(highest_prior_seq_number, sequence_number);
720 ++window_index_begin;
721 }
Bjorn Terelius068fc352019-02-13 22:38:25 +0100722 float x = config_.GetCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200723 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800724 if (expected_packets > 0) {
725 int64_t received_packets = window_index_end - window_index_begin;
726 int64_t lost_packets = expected_packets - received_packets;
727 float y = static_cast<float>(lost_packets) / expected_packets * 100;
728 time_series.points.emplace_back(x, y);
729 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200730 }
philipel35ba9bd2017-04-19 05:58:51 -0700731 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200732 }
733
Bjorn Terelius068fc352019-02-13 22:38:25 +0100734 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
735 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100736 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
737 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
Stefan Holmer99f8e082016-09-09 13:37:50 +0200738}
739
terelius2ee076d2017-08-15 02:04:02 -0700740void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100741 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200742 // Filter on SSRC.
743 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Terelius48b82792020-05-19 10:57:24 +0200744 IsRtxSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700745 continue;
746 }
terelius54ce6802016-07-13 06:44:41 -0700747
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100748 const std::vector<LoggedRtpPacketIncoming>& packets =
749 stream.incoming_packets;
750 if (packets.size() < 100) {
751 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
752 << packets.size() << " packets in the stream.";
753 continue;
754 }
Björn Terelius0d1b28c2020-05-27 20:25:06 +0200755 int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100756 absl::optional<uint32_t> estimated_frequency =
Bjorn Terelius48b82792020-05-19 10:57:24 +0200757 EstimateRtpClockFrequency(packets, segment_end_us);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100758 if (!estimated_frequency)
759 continue;
760 const double frequency_hz = *estimated_frequency;
Bjorn Terelius48b82792020-05-19 10:57:24 +0200761 if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc) &&
762 frequency_hz != 90000) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100763 RTC_LOG(LS_WARNING)
764 << "Video stream should use a 90 kHz clock but appears to use "
765 << frequency_hz / 1000 << ". Discarding.";
766 continue;
767 }
768
769 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100770 return this->config_.GetCallTimeSec(packet.log_time_us());
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100771 };
772 auto ToNetworkDelay = [frequency_hz](
773 const LoggedRtpPacketIncoming& old_packet,
774 const LoggedRtpPacketIncoming& new_packet) {
775 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
776 };
777
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200778 TimeSeries capture_time_data(
Bjorn Terelius48b82792020-05-19 10:57:24 +0200779 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) +
780 " capture-time",
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200781 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100782 AccumulatePairs<LoggedRtpPacketIncoming, double>(
783 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700784 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700785
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200786 TimeSeries send_time_data(
Bjorn Terelius48b82792020-05-19 10:57:24 +0200787 GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) +
788 " abs-send-time",
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200789 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100790 AccumulatePairs<LoggedRtpPacketIncoming, double>(
791 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
792 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700793 }
794
Bjorn Terelius068fc352019-02-13 22:38:25 +0100795 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
796 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +0100797 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
798 plot->SetTitle("Incoming network delay (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700799}
800
tereliusf736d232016-08-04 10:00:11 -0700801// Plot the fraction of packets lost (as perceived by the loss-based BWE).
802void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100803 TimeSeries time_series("Fraction lost", LineStyle::kLine,
804 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200805 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100806 float x = config_.GetCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200807 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700808 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700809 }
tereliusf736d232016-08-04 10:00:11 -0700810
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200811 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +0100812 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
813 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100814 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
815 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
tereliusf736d232016-08-04 10:00:11 -0700816}
817
terelius54ce6802016-07-13 06:44:41 -0700818// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200819void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
820 // TODO(terelius): This could be provided by the parser.
821 std::multimap<int64_t, size_t> packets_in_order;
822 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
823 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
824 packets_in_order.insert(
825 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700826 }
827
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200828 auto window_begin = packets_in_order.begin();
829 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700830 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700831
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800832 if (!packets_in_order.empty()) {
833 // Calculate a moving average of the bitrate and store in a TimeSeries.
834 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
835 for (int64_t time = config_.begin_time_;
836 time < config_.end_time_ + config_.step_; time += config_.step_) {
837 while (window_end != packets_in_order.end() && window_end->first < time) {
838 bytes_in_window += window_end->second;
839 ++window_end;
840 }
841 while (window_begin != packets_in_order.end() &&
842 window_begin->first < time - config_.window_duration_) {
843 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
844 bytes_in_window -= window_begin->second;
845 ++window_begin;
846 }
847 float window_duration_in_seconds =
848 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
849 float x = config_.GetCallTimeSec(time);
850 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
851 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700852 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800853 plot->AppendTimeSeries(std::move(bitrate_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200854 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200855
856 // Overlay the outgoing REMB over incoming bitrate.
857 TimeSeries remb_series("Remb", LineStyle::kStep);
858 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100859 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200860 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
861 remb_series.points.emplace_back(x, y);
862 }
863 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
864
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800865 if (!parsed_log_.generic_packets_received().empty()) {
866 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
867 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
868 return packet.packet_length * 8.0 / 1000.0;
869 };
870 MovingAverage<LoggedGenericPacketReceived, double>(
871 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
872 &time_series);
873 plot->AppendTimeSeries(std::move(time_series));
874 }
875
Bjorn Terelius068fc352019-02-13 22:38:25 +0100876 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
877 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200878 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
879 plot->SetTitle("Incoming RTP bitrate");
880}
881
882// Plot the total bandwidth used by all RTP streams.
883void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
884 bool show_detector_state,
885 bool show_alr_state) {
886 // TODO(terelius): This could be provided by the parser.
887 std::multimap<int64_t, size_t> packets_in_order;
888 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
889 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
890 packets_in_order.insert(
891 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
892 }
893
894 auto window_begin = packets_in_order.begin();
895 auto window_end = packets_in_order.begin();
896 size_t bytes_in_window = 0;
897
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800898 if (!packets_in_order.empty()) {
899 // Calculate a moving average of the bitrate and store in a TimeSeries.
900 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
901 for (int64_t time = config_.begin_time_;
902 time < config_.end_time_ + config_.step_; time += config_.step_) {
903 while (window_end != packets_in_order.end() && window_end->first < time) {
904 bytes_in_window += window_end->second;
905 ++window_end;
906 }
907 while (window_begin != packets_in_order.end() &&
908 window_begin->first < time - config_.window_duration_) {
909 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
910 bytes_in_window -= window_begin->second;
911 ++window_begin;
912 }
913 float window_duration_in_seconds =
914 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
915 float x = config_.GetCallTimeSec(time);
916 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
917 bitrate_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200918 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800919 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700920 }
921
terelius8058e582016-07-25 01:32:41 -0700922 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200923 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
924 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100925 float x = config_.GetCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200926 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
927 loss_series.points.emplace_back(x, y);
928 }
philipel10fc0e62017-04-11 01:50:23 -0700929
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200930 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
931 IntervalSeries overusing_series("Overusing", "#ff8e82",
932 IntervalSeries::kHorizontal);
933 IntervalSeries underusing_series("Underusing", "#5092fc",
934 IntervalSeries::kHorizontal);
935 IntervalSeries normal_series("Normal", "#c4ffc4",
936 IntervalSeries::kHorizontal);
937 IntervalSeries* last_series = &normal_series;
938 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700939
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200940 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700941
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200942 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100943 float x = config_.GetCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200944 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700945
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200946 if (last_detector_state != delay_update.detector_state) {
947 last_series->intervals.emplace_back(last_detector_switch, x);
948 last_detector_state = delay_update.detector_state;
949 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700950
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200951 switch (delay_update.detector_state) {
952 case BandwidthUsage::kBwNormal:
953 last_series = &normal_series;
954 break;
955 case BandwidthUsage::kBwUnderusing:
956 last_series = &underusing_series;
957 break;
958 case BandwidthUsage::kBwOverusing:
959 last_series = &overusing_series;
960 break;
961 case BandwidthUsage::kLast:
962 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200963 }
964 }
philipel23c7f252017-07-14 06:30:03 -0700965
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200966 delay_series.points.emplace_back(x, y);
967 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200968
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200969 RTC_CHECK(last_series);
Bjorn Terelius068fc352019-02-13 22:38:25 +0100970 last_series->intervals.emplace_back(last_detector_switch, config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200971
972 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
973 PointStyle::kHighlight);
974 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100975 float x = config_.GetCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200976 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
977 created_series.points.emplace_back(x, y);
978 }
979
980 TimeSeries result_series("Probing results.", LineStyle::kNone,
981 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200982 for (auto& result : parsed_log_.bwe_probe_success_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100983 float x = config_.GetCallTimeSec(result.log_time_us());
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200984 float y = static_cast<float>(result.bitrate_bps) / 1000;
985 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200986 }
987
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -0800988 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
989 PointStyle::kHighlight);
990 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100991 float x = config_.GetCallTimeSec(failure.log_time_us());
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -0800992 probe_failures_series.points.emplace_back(x, 0);
993 }
994
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200995 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
996 bool previously_in_alr = false;
997 int64_t alr_start = 0;
998 for (auto& alr : parsed_log_.alr_state_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100999 float y = config_.GetCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001000 if (!previously_in_alr && alr.in_alr) {
1001 alr_start = alr.log_time_us();
1002 previously_in_alr = true;
1003 } else if (previously_in_alr && !alr.in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001004 float x = config_.GetCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +01001005 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001006 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +00001007 }
Björn Tereliusff612732018-04-25 14:23:01 +00001008 }
1009
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001010 if (previously_in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001011 float x = config_.GetCallTimeSec(alr_start);
1012 float y = config_.GetCallTimeSec(config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001013 alr_state.intervals.emplace_back(x, y);
1014 }
1015
1016 if (show_detector_state) {
1017 plot->AppendIntervalSeries(std::move(overusing_series));
1018 plot->AppendIntervalSeries(std::move(underusing_series));
1019 plot->AppendIntervalSeries(std::move(normal_series));
1020 }
1021
1022 if (show_alr_state) {
1023 plot->AppendIntervalSeries(std::move(alr_state));
1024 }
1025 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001026 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001027 plot->AppendTimeSeries(std::move(delay_series));
1028 plot->AppendTimeSeries(std::move(created_series));
1029 plot->AppendTimeSeries(std::move(result_series));
1030
1031 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001032 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001033 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001034 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001035 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001036 remb_series.points.emplace_back(x, y);
1037 }
1038 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1039
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001040 if (!parsed_log_.generic_packets_sent().empty()) {
1041 {
1042 TimeSeries time_series("Outgoing generic total bitrate",
1043 LineStyle::kLine);
1044 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1045 return packet.packet_length() * 8.0 / 1000.0;
1046 };
1047 MovingAverage<LoggedGenericPacketSent, double>(
1048 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1049 &time_series);
1050 plot->AppendTimeSeries(std::move(time_series));
1051 }
1052
1053 {
1054 TimeSeries time_series("Outgoing generic payload bitrate",
1055 LineStyle::kLine);
1056 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1057 return packet.payload_length * 8.0 / 1000.0;
1058 };
1059 MovingAverage<LoggedGenericPacketSent, double>(
1060 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1061 &time_series);
1062 plot->AppendTimeSeries(std::move(time_series));
1063 }
1064 }
1065
Bjorn Terelius068fc352019-02-13 22:38:25 +01001066 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1067 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001068 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001069 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001070}
1071
1072// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001073void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1074 Plot* plot) {
1075 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1076 // Filter on SSRC.
1077 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001078 continue;
terelius54ce6802016-07-13 06:44:41 -07001079 }
1080
Bjorn Terelius48b82792020-05-19 10:57:24 +02001081 TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001082 LineStyle::kLine);
1083 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1084 return packet.total_length * 8.0 / 1000.0;
1085 };
terelius53dc23c2017-03-13 05:24:05 -07001086 MovingAverage<LoggedRtpPacket, double>(
Bjorn Terelius068fc352019-02-13 22:38:25 +01001087 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001088 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001089 }
1090
Bjorn Terelius068fc352019-02-13 22:38:25 +01001091 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1092 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001093 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001094 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001095}
1096
Bjorn Terelius9775a582019-02-15 17:29:58 +01001097// Plot the bitrate allocation for each temporal and spatial layer.
1098// Computed from RTCP XR target bitrate block, so the graph is only populated if
1099// those are sent.
1100void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1101 Plot* plot) {
1102 std::map<LayerDescription, TimeSeries> time_series;
1103 const auto& xr_list = parsed_log_.extended_reports(direction);
1104 for (const auto& rtcp : xr_list) {
1105 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1106 rtcp.xr.target_bitrate();
1107 if (!target_bitrate.has_value())
1108 continue;
1109 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1110 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1111 bitrate_item.temporal_layer);
1112 auto time_series_it = time_series.find(layer);
1113 if (time_series_it == time_series.end()) {
1114 std::string layer_name = GetLayerName(layer);
1115 bool inserted;
1116 std::tie(time_series_it, inserted) = time_series.insert(
1117 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1118 RTC_DCHECK(inserted);
1119 }
1120 float x = config_.GetCallTimeSec(rtcp.log_time_us());
1121 float y = bitrate_item.target_bitrate_kbps;
1122 time_series_it->second.points.emplace_back(x, y);
1123 }
1124 }
1125 for (auto& layer : time_series) {
1126 plot->AppendTimeSeries(std::move(layer.second));
1127 }
1128 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1129 "Time (s)", kLeftMargin, kRightMargin);
1130 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1131 if (direction == kIncomingPacket)
1132 plot->SetTitle("Target bitrate per incoming layer");
1133 else
1134 plot->SetTitle("Target bitrate per outgoing layer");
1135}
1136
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001137void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1138 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1139 PointStyle::kHighlight);
1140 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1141 PointStyle::kHighlight);
1142 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1143 PointStyle::kHighlight);
1144 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1145 PointStyle::kHighlight);
1146
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001147 LogBasedNetworkControllerSimulation simulation(
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001148 std::make_unique<GoogCcNetworkControllerFactory>(),
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001149 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1150 if (update.target_rate) {
1151 target_rates.points.emplace_back(
1152 config_.GetCallTimeSec(at_time.us()),
1153 update.target_rate->target_rate.kbps<float>());
1154 }
1155 });
1156
1157 simulation.ProcessEventsInLog(parsed_log_);
1158 for (const auto& logged : parsed_log_.bwe_delay_updates())
1159 delay_based.points.emplace_back(
1160 config_.GetCallTimeSec(logged.log_time_us()),
1161 logged.bitrate_bps / 1000);
1162 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1163 probe_results.points.emplace_back(
1164 config_.GetCallTimeSec(logged.log_time_us()),
1165 logged.bitrate_bps / 1000);
1166 for (const auto& logged : parsed_log_.bwe_loss_updates())
1167 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time_us()),
1168 logged.bitrate_bps / 1000);
1169
1170 plot->AppendTimeSeries(std::move(delay_based));
1171 plot->AppendTimeSeries(std::move(loss_based));
1172 plot->AppendTimeSeries(std::move(probe_results));
1173 plot->AppendTimeSeries(std::move(target_rates));
1174
1175 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1176 "Time (s)", kLeftMargin, kRightMargin);
1177 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1178 plot->SetTitle("Simulated BWE behavior");
1179}
1180
Bjorn Terelius28db2662017-10-04 14:22:43 +02001181void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001182 using RtpPacketType = LoggedRtpPacketOutgoing;
1183 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001184
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001185 // TODO(terelius): This could be provided by the parser.
1186 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1187 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1188 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1189 outgoing_rtp.insert(
1190 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001191 }
1192
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001193 const std::vector<TransportFeedbackType>& incoming_rtcp =
1194 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001195
1196 SimulatedClock clock(0);
1197 BitrateObserver observer;
Danil Chapovalov83bbe912019-08-07 12:24:53 +02001198 RtcEventLogNull null_event_log;
nisse0245da02016-11-30 03:35:20 -08001199 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001200 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001201 TransportFeedbackAdapter transport_feedback;
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001202 auto factory = GoogCcNetworkControllerFactory();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001203 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001204 // TODO(holmer): Log the call config and use that here instead.
1205 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001206 NetworkControllerConfig cc_config;
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001207 cc_config.constraints.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
Danil Chapovalovcad3e0e2020-02-17 18:46:07 +01001208 cc_config.constraints.starting_rate =
1209 DataRate::BitsPerSec(kDefaultStartBitrateBps);
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001210 cc_config.event_log = &null_event_log;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001211 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001212
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001213 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1214 PointStyle::kHighlight);
1215 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1216 PointStyle::kHighlight);
1217 TimeSeries acked_estimate_time_series(
1218 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001219
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())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001231 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001232 return std::numeric_limits<int64_t>::max();
1233 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001234 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001235
1236 auto NextProcessTime = [&]() {
1237 if (rtcp_iterator != incoming_rtcp.end() ||
1238 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001239 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001240 }
1241 return std::numeric_limits<int64_t>::max();
1242 };
1243
Stefan Holmer492ee282016-10-27 17:19:20 +02001244 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001245#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001246 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001247 // The event_log_visualizer should normally not be compiled with
1248 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
Björn Terelius251b0dc2019-11-11 21:00:18 +01001249 // However, compiling with BWE_TEST_LOGGING, running with --plot=sendside_bwe
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001250 // and piping the output to plot_dynamics.py can be used as a hack to get the
1251 // internal state of various BWE components. In this case, it is important
1252 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
Sebastian Jansson4ad51d82019-06-11 11:24:40 +02001253 // GoogCcNetworkController since that would lead to duplicate outputs.
Björn Terelius251b0dc2019-11-11 21:00:18 +01001254 std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1255 acknowledged_bitrate_estimator(
1256 AcknowledgedBitrateEstimatorInterface::Create(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001257#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001258 int64_t time_us =
1259 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001260 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001261 while (time_us != std::numeric_limits<int64_t>::max()) {
1262 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001263 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1264 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1265 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1266 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1267 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
Erik Språng30a276b2019-04-23 12:00:11 +02001268 RtpPacketSendInfo packet_info;
1269 packet_info.ssrc = rtp_packet.rtp.header.ssrc;
Bjorn Tereliusf2e9cab2019-05-27 16:44:09 +02001270 packet_info.transport_sequence_number =
Erik Språng30a276b2019-04-23 12:00:11 +02001271 rtp_packet.rtp.header.extension.transportSequenceNumber;
1272 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
Erik Språng30a276b2019-04-23 12:00:11 +02001273 packet_info.length = rtp_packet.rtp.total_length;
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001274 transport_feedback.AddPacket(
Erik Språng30a276b2019-04-23 12:00:11 +02001275 packet_info,
1276 0u, // Per packet overhead bytes.
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001277 Timestamp::Micros(rtp_packet.rtp.log_time_us()));
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001278 rtc::SentPacket sent_packet(
1279 rtp_packet.rtp.header.extension.transportSequenceNumber,
1280 rtp_packet.rtp.log_time_us() / 1000);
1281 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1282 if (sent_msg)
1283 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1284 }
1285 ++rtp_iterator;
1286 }
Stefan Holmer13181032016-07-29 14:48:54 +02001287 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001288 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001289
1290 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001291 rtcp_iterator->transport_feedback,
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001292 Timestamp::Millis(clock.TimeInMilliseconds()));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001293 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001294 if (feedback_msg) {
1295 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001296 std::vector<PacketResult> feedback =
1297 feedback_msg->SortedByReceiveTime();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001298 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001299#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Björn Terelius251b0dc2019-11-11 21:00:18 +01001300 acknowledged_bitrate_estimator->IncomingPacketFeedbackVector(
1301 feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001302#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001303 for (const PacketResult& packet : feedback)
1304 acked_bitrate.Update(packet.sent_packet.size.bytes(),
1305 packet.receive_time.ms());
1306 bitrate_bps = acked_bitrate.Rate(feedback.back().receive_time.ms());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001307 }
Stefan Holmer13181032016-07-29 14:48:54 +02001308 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001309
Bjorn Terelius068fc352019-02-13 22:38:25 +01001310 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001311 float y = bitrate_bps.value_or(0) / 1000;
1312 acked_time_series.points.emplace_back(x, y);
1313#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Björn Terelius251b0dc2019-11-11 21:00:18 +01001314 y = acknowledged_bitrate_estimator->bitrate()
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001315 .value_or(DataRate::Zero())
1316 .kbps();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001317 acked_estimate_time_series.points.emplace_back(x, y);
1318#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001319 ++rtcp_iterator;
1320 }
stefanc3de0332016-08-02 07:22:17 -07001321 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1322 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001323 ProcessInterval msg;
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001324 msg.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001325 observer.Update(goog_cc->OnProcessInterval(msg));
1326 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001327 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001328 if (observer.GetAndResetBitrateUpdated() ||
1329 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001330 uint32_t y = observer.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001331 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001332 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001333 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001334 }
1335 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1336 }
1337 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001338 plot->AppendTimeSeries(std::move(time_series));
1339 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001340 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001341
Bjorn Terelius068fc352019-02-13 22:38:25 +01001342 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1343 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001344 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001345 plot->SetTitle("Simulated send-side BWE behavior");
1346}
1347
1348void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001349 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001350 class RembInterceptingPacketRouter : public PacketRouter {
1351 public:
1352 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1353 uint32_t bitrate_bps) override {
1354 last_bitrate_bps_ = bitrate_bps;
1355 bitrate_updated_ = true;
1356 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1357 }
1358 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1359 bool GetAndResetBitrateUpdated() {
1360 bool bitrate_updated = bitrate_updated_;
1361 bitrate_updated_ = false;
1362 return bitrate_updated;
1363 }
1364
1365 private:
Bjorn Terelius571e1302020-06-09 10:29:09 +02001366 // We don't know the start bitrate, but assume that it is the default 300
1367 // kbps.
1368 uint32_t last_bitrate_bps_ = 300000;
1369 bool bitrate_updated_ = false;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001370 };
1371
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001372 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001373
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001374 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Terelius48b82792020-05-19 10:57:24 +02001375 if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001376 for (const auto& rtp_packet : stream.incoming_packets)
1377 incoming_rtp.insert(
1378 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001379 }
1380 }
1381
1382 SimulatedClock clock(0);
1383 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001384 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001385 // Is this intentional?
1386 ReceiveSideCongestionController rscc(&clock, &packet_router);
1387 // TODO(holmer): Log the call config and use that here instead.
1388 // static const uint32_t kDefaultStartBitrateBps = 300000;
1389 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1390
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001391 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1392 PointStyle::kHighlight);
1393 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001394
1395 RateStatistics acked_bitrate(250, 8000);
1396 int64_t last_update_us = 0;
1397 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001398 const RtpPacketType& packet = *kv.second;
1399 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1400 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1401 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001402 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001403 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001404 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001405 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001406 if (bitrate_bps) {
1407 uint32_t y = *bitrate_bps / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001408 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001409 acked_time_series.points.emplace_back(x, y);
1410 }
1411 if (packet_router.GetAndResetBitrateUpdated() ||
1412 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1413 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001414 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001415 time_series.points.emplace_back(x, y);
1416 last_update_us = clock.TimeInMicroseconds();
1417 }
1418 }
1419 // Add the data set to the plot.
1420 plot->AppendTimeSeries(std::move(time_series));
1421 plot->AppendTimeSeries(std::move(acked_time_series));
1422
Bjorn Terelius068fc352019-02-13 22:38:25 +01001423 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1424 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001425 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1426 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001427}
1428
tereliuse34c19c2016-08-15 08:47:14 -07001429void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001430 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001431 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001432 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1433 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001434
stefana0a8ed72017-09-06 02:06:32 -07001435 int64_t prev_y = 0;
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001436 std::vector<MatchedSendArrivalTimes> matched_rtp_rtcp =
1437 GetNetworkTrace(parsed_log_);
1438 absl::c_stable_sort(matched_rtp_rtcp, [](const MatchedSendArrivalTimes& a,
1439 const MatchedSendArrivalTimes& b) {
philipel3574d052019-11-18 14:38:13 +01001440 return a.feedback_arrival_time_ms < b.feedback_arrival_time_ms ||
1441 (a.feedback_arrival_time_ms == b.feedback_arrival_time_ms &&
1442 a.arrival_time_ms < b.arrival_time_ms);
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001443 });
1444 for (const auto& packet : matched_rtp_rtcp) {
Sebastian Jansson74f96ec2019-10-29 12:57:54 +01001445 if (packet.arrival_time_ms == MatchedSendArrivalTimes::kNotReceived)
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001446 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001447 float x = config_.GetCallTimeSec(1000 * packet.feedback_arrival_time_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001448 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1449 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001450 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1451 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1452 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001453 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001454 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001455
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001456 // We assume that the base network delay (w/o queues) is equal to half
1457 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
Mirko Bonadei604e75c2019-07-25 11:55:47 +02001458 // observed 1-ways delay and add half the minimum RTT.
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001459 const int64_t estimated_clock_offset_ms =
1460 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001461 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001462 point.y -= estimated_clock_offset_ms;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001463
stefanc3de0332016-08-02 07:22:17 -07001464 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001465 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
stefanc3de0332016-08-02 07:22:17 -07001466
Bjorn Terelius068fc352019-02-13 22:38:25 +01001467 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1468 "Time (s)", kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001469 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +01001470 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001471}
stefan08383272016-12-20 08:51:52 -08001472
Bjorn Terelius0295a962017-10-25 17:42:41 +02001473void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001474 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1475 const std::vector<LoggedRtpPacketOutgoing>& packets =
1476 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001477
Bjorn Terelius48b82792020-05-19 10:57:24 +02001478 if (IsRtxSsrc(parsed_log_, kOutgoingPacket, stream.ssrc)) {
Konrad Hofbauerbfb735b2019-04-16 11:12:11 +02001479 continue;
1480 }
1481
Bjorn Terelius0295a962017-10-25 17:42:41 +02001482 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001483 RTC_LOG(LS_WARNING)
1484 << "Can't estimate a the RTP clock frequency or the "
1485 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001486 continue;
1487 }
Björn Terelius0d1b28c2020-05-27 20:25:06 +02001488 int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
Danil Chapovalov431abd92018-06-18 12:54:17 +02001489 absl::optional<uint32_t> estimated_frequency =
Bjorn Terelius48b82792020-05-19 10:57:24 +02001490 EstimateRtpClockFrequency(packets, segment_end_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001491 if (!estimated_frequency)
1492 continue;
Bjorn Terelius48b82792020-05-19 10:57:24 +02001493 if (IsVideoSsrc(parsed_log_, kOutgoingPacket, stream.ssrc) &&
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001494 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001495 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001496 << "Video stream should use a 90 kHz clock but appears to use "
1497 << *estimated_frequency / 1000 << ". Discarding.";
1498 continue;
1499 }
1500
1501 TimeSeries pacer_delay_series(
Bjorn Terelius48b82792020-05-19 10:57:24 +02001502 GetStreamName(parsed_log_, kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001503 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001504 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001505 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1506 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001507 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1508 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1509 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001510 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001511 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001512 first_capture_timestamp) /
1513 *estimated_frequency * 1000;
1514 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001515 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1516 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001517 float x = config_.GetCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001518 float y = send_time_ms - capture_time_ms;
1519 pacer_delay_series.points.emplace_back(x, y);
1520 }
1521 plot->AppendTimeSeries(std::move(pacer_delay_series));
1522 }
1523
Bjorn Terelius068fc352019-02-13 22:38:25 +01001524 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1525 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001526 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1527 plot->SetTitle(
1528 "Delay from capture to send time. (First packet normalized to 0.)");
1529}
1530
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001531void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1532 Plot* plot) {
1533 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1534 TimeSeries rtp_timestamps(
Bjorn Terelius48b82792020-05-19 10:57:24 +02001535 GetStreamName(parsed_log_, direction, stream.ssrc) + " capture-time",
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001536 LineStyle::kLine, PointStyle::kHighlight);
1537 for (const auto& packet : stream.packet_view) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001538 float x = config_.GetCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001539 float y = packet.header.timestamp;
1540 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001541 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001542 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001543
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001544 TimeSeries rtcp_timestamps(
Bjorn Terelius48b82792020-05-19 10:57:24 +02001545 GetStreamName(parsed_log_, direction, stream.ssrc) +
1546 " rtcp capture-time",
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001547 LineStyle::kLine, PointStyle::kHighlight);
1548 // TODO(terelius): Why only sender reports?
1549 const auto& sender_reports = parsed_log_.sender_reports(direction);
1550 for (const auto& rtcp : sender_reports) {
1551 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1552 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001553 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001554 float y = rtcp.sr.rtp_timestamp();
1555 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001556 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001557 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001558 }
1559
Bjorn Terelius068fc352019-02-13 22:38:25 +01001560 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1561 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001562 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1563 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001564}
michaelt6e5b2192017-02-22 07:33:27 -08001565
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001566void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1567 PacketDirection direction,
1568 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1569 std::string title,
1570 std::string yaxis_label,
1571 Plot* plot) {
1572 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1573 const auto& sender_reports = parsed_log_.sender_reports(direction);
1574 for (const auto& rtcp : sender_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001575 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001576 uint32_t ssrc = rtcp.sr.sender_ssrc();
1577 for (const auto& block : rtcp.sr.report_blocks()) {
1578 float y = fy(block);
1579 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1580 bool inserted;
1581 if (sr_report_it == sr_reports_by_ssrc.end()) {
1582 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
Bjorn Terelius48b82792020-05-19 10:57:24 +02001583 ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) +
1584 " Sender Reports",
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001585 LineStyle::kLine, PointStyle::kHighlight));
1586 }
1587 sr_report_it->second.points.emplace_back(x, y);
1588 }
1589 }
1590 for (auto& kv : sr_reports_by_ssrc) {
1591 plot->AppendTimeSeries(std::move(kv.second));
1592 }
1593
1594 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1595 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1596 for (const auto& rtcp : receiver_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001597 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001598 uint32_t ssrc = rtcp.rr.sender_ssrc();
1599 for (const auto& block : rtcp.rr.report_blocks()) {
1600 float y = fy(block);
1601 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1602 bool inserted;
1603 if (rr_report_it == rr_reports_by_ssrc.end()) {
1604 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
Bjorn Terelius48b82792020-05-19 10:57:24 +02001605 ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) +
1606 " Receiver Reports",
1607 LineStyle::kLine, PointStyle::kHighlight));
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001608 }
1609 rr_report_it->second.points.emplace_back(x, y);
1610 }
1611 }
1612 for (auto& kv : rr_reports_by_ssrc) {
1613 plot->AppendTimeSeries(std::move(kv.second));
1614 }
1615
Bjorn Terelius068fc352019-02-13 22:38:25 +01001616 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1617 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001618 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1619 plot->SetTitle(title);
1620}
1621
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001622void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1623 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001624 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001625 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1626 configs_by_cp_id.end()) {
1627 const std::string candidate_pair_desc =
1628 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001629 configs_by_cp_id[config.candidate_pair_id] =
1630 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1631 candidate_pair_desc,
1632 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001633 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1634 candidate_pair_desc;
1635 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01001636 float x = config_.GetCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001637 float y = static_cast<float>(config.type);
1638 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1639 }
1640
1641 // TODO(qingsi): There can be a large number of candidate pairs generated by
1642 // certain calls and the frontend cannot render the chart in this case due to
1643 // the failure of generating a palette with the same number of colors.
1644 for (auto& kv : configs_by_cp_id) {
1645 plot->AppendTimeSeries(std::move(kv.second));
1646 }
1647
Bjorn Terelius068fc352019-02-13 22:38:25 +01001648 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1649 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001650 plot->SetSuggestedYAxis(0, 3, "Config Type", kBottomMargin, kTopMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001651 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001652 plot->SetYAxisTickLabels(
1653 {{static_cast<float>(IceCandidatePairConfigType::kAdded), "ADDED"},
1654 {static_cast<float>(IceCandidatePairConfigType::kUpdated), "UPDATED"},
1655 {static_cast<float>(IceCandidatePairConfigType::kDestroyed),
1656 "DESTROYED"},
1657 {static_cast<float>(IceCandidatePairConfigType::kSelected),
1658 "SELECTED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001659}
1660
1661std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1662 uint32_t candidate_pair_id) {
1663 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1664 candidate_pair_desc_by_id_.end()) {
1665 return candidate_pair_desc_by_id_[candidate_pair_id];
1666 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001667 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001668 // TODO(qingsi): Add the handling of the "Updated" config event after the
1669 // visualization of property change for candidate pairs is introduced.
1670 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1671 candidate_pair_desc_by_id_.end()) {
1672 const std::string candidate_pair_desc =
1673 GetCandidatePairLogDescriptionAsString(config);
1674 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1675 candidate_pair_desc;
1676 }
1677 }
1678 return candidate_pair_desc_by_id_[candidate_pair_id];
1679}
1680
1681void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001682 constexpr int kEventTypeOffset =
1683 static_cast<int>(IceCandidatePairConfigType::kNumValues);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001684 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001685 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001686 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1687 checks_by_cp_id.end()) {
1688 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08001689 "[" + std::to_string(event.candidate_pair_id) + "]" +
1690 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001691 LineStyle::kNone, PointStyle::kHighlight);
1692 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01001693 float x = config_.GetCallTimeSec(event.log_time_us());
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001694 float y = static_cast<float>(event.type) + kEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001695 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1696 }
1697
1698 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1699 for (auto& kv : checks_by_cp_id) {
1700 plot->AppendTimeSeries(std::move(kv.second));
1701 }
1702
Bjorn Terelius068fc352019-02-13 22:38:25 +01001703 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1704 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001705 plot->SetSuggestedYAxis(0, 4, "Connectivity State", kBottomMargin,
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001706 kTopMargin);
1707 plot->SetTitle("[IceEventLog] ICE connectivity checks");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001708
1709 plot->SetYAxisTickLabels(
1710 {{static_cast<float>(IceCandidatePairEventType::kCheckSent) +
1711 kEventTypeOffset,
1712 "CHECK SENT"},
1713 {static_cast<float>(IceCandidatePairEventType::kCheckReceived) +
1714 kEventTypeOffset,
1715 "CHECK RECEIVED"},
1716 {static_cast<float>(IceCandidatePairEventType::kCheckResponseSent) +
1717 kEventTypeOffset,
1718 "RESPONSE SENT"},
1719 {static_cast<float>(IceCandidatePairEventType::kCheckResponseReceived) +
1720 kEventTypeOffset,
1721 "RESPONSE RECEIVED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001722}
1723
Zach Stein10a58012018-12-07 12:26:28 -08001724void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
1725 TimeSeries states("DTLS Transport State", LineStyle::kNone,
1726 PointStyle::kHighlight);
1727 for (const auto& event : parsed_log_.dtls_transport_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001728 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08001729 float y = static_cast<float>(event.dtls_transport_state);
1730 states.points.emplace_back(x, y);
1731 }
1732 plot->AppendTimeSeries(std::move(states));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001733 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1734 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08001735 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001736 "Transport State", kBottomMargin, kTopMargin);
Zach Stein10a58012018-12-07 12:26:28 -08001737 plot->SetTitle("DTLS Transport State");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02001738 plot->SetYAxisTickLabels(
1739 {{static_cast<float>(DtlsTransportState::kNew), "NEW"},
1740 {static_cast<float>(DtlsTransportState::kConnecting), "CONNECTING"},
1741 {static_cast<float>(DtlsTransportState::kConnected), "CONNECTED"},
1742 {static_cast<float>(DtlsTransportState::kClosed), "CLOSED"},
1743 {static_cast<float>(DtlsTransportState::kFailed), "FAILED"}});
Zach Stein10a58012018-12-07 12:26:28 -08001744}
1745
1746void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
1747 TimeSeries writable("DTLS Writable", LineStyle::kNone,
1748 PointStyle::kHighlight);
1749 for (const auto& event : parsed_log_.dtls_writable_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001750 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08001751 float y = static_cast<float>(event.writable);
1752 writable.points.emplace_back(x, y);
1753 }
1754 plot->AppendTimeSeries(std::move(writable));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001755 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1756 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08001757 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
1758 plot->SetTitle("DTLS Writable State");
1759}
1760
terelius54ce6802016-07-13 06:44:41 -07001761} // namespace webrtc