blob: 11e33f29e2df7d2f892fe7f528fc187592fa4815 [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 Bonadei92ea95e2017-09-15 06:47:31 +020011#include "rtc_tools/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>
terelius54ce6802016-07-13 06:44:41 -070017#include <string>
18#include <utility>
19
Karl Wiberg918f50c2018-07-05 11:40:33 +020020#include "absl/memory/memory.h"
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +010021#include "absl/strings/string_view.h"
Artem Titov741daaf2019-03-21 14:37:36 +010022#include "api/function_view.h"
Sebastian Jansson95edb032019-01-17 16:24:12 +010023#include "api/transport/field_trial_based_config.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020024#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020025#include "call/audio_receive_stream.h"
26#include "call/audio_send_stream.h"
27#include "call/call.h"
28#include "call/video_receive_stream.h"
29#include "call/video_send_stream.h"
Elad Alon99a81b62017-09-21 10:25:29 +020030#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020031#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020032#include "modules/audio_coding/neteq/tools/audio_sink.h"
33#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
34#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
35#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
36#include "modules/audio_coding/neteq/tools/neteq_test.h"
37#include "modules/audio_coding/neteq/tools/resample_input_audio_file.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020038#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
39#include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020040#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020041#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020042#include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
Erik Språnge7942432019-06-12 13:30:02 +020043#include "modules/pacing/paced_sender.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010044#include "modules/pacing/packet_router.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020045#include "modules/remote_bitrate_estimator/include/bwe_defines.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020046#include "modules/rtp_rtcp/include/rtp_rtcp.h"
47#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020048#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020049#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
50#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
51#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
52#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
53#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
54#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
55#include "modules/rtp_rtcp/source/rtp_utility.h"
56#include "rtc_base/checks.h"
57#include "rtc_base/format_macros.h"
58#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020059#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020060#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020061#include "rtc_base/strings/string_builder.h"
Sebastian Jansson1175ae02019-03-13 08:56:58 +010062#include "rtc_tools/event_log_visualizer/log_simulation.h"
terelius54ce6802016-07-13 06:44:41 -070063
Bjorn Terelius6984ad22017-10-24 12:19:45 +020064#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
65#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
66#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
67
tereliusdc35dcd2016-08-01 12:03:27 -070068namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070069
terelius54ce6802016-07-13 06:44:41 -070070namespace {
71
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080072const int kNumMicrosecsPerSec = 1000000;
73
terelius54ce6802016-07-13 06:44:41 -070074std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020075 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070076 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020077 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070078}
79
80// Checks whether an SSRC is contained in the list of desired SSRCs.
81// Note that an empty SSRC list matches every SSRC.
82bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
83 if (desired_ssrc.size() == 0)
84 return true;
85 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
86 desired_ssrc.end();
87}
88
89double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
90 // The timestamp is a fixed point representation with 6 bits for seconds
91 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080092 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
93 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070094 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080095 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -070096 return abs_send_time * kTimestampToMicroSec;
97}
98
99// Computes the difference |later| - |earlier| where |later| and |earlier|
100// are counters that wrap at |modulus|. The difference is chosen to have the
101// least absolute value. For example if |modulus| is 8, then the difference will
102// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
103// be in [-4, 4].
104int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
105 RTC_DCHECK_LE(1, modulus);
106 RTC_DCHECK_LT(later, modulus);
107 RTC_DCHECK_LT(earlier, modulus);
108 int64_t difference =
109 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
110 int64_t max_difference = modulus / 2;
111 int64_t min_difference = max_difference - modulus + 1;
112 if (difference > max_difference) {
113 difference -= modulus;
114 }
115 if (difference < min_difference) {
116 difference += modulus;
117 }
terelius6addf492016-08-23 17:34:07 -0700118 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100119 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
120 << " expected to be in the range ("
121 << min_difference / 2 << "," << max_difference / 2
122 << ") but is " << difference
123 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700124 }
terelius54ce6802016-07-13 06:44:41 -0700125 return difference;
126}
127
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200128// This is much more reliable for outgoing streams than for incoming streams.
129template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200130absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200131 const RtpPacketContainer& packets,
132 int64_t end_time_us) {
133 RTC_CHECK(packets.size() >= 2);
134 SeqNumUnwrapper<uint32_t> unwrapper;
Philip Eliasson1f850a62019-03-19 12:15:00 +0000135 int64_t first_rtp_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200136 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
137 int64_t first_log_timestamp = packets[0].log_time_us();
Philip Eliasson1f850a62019-03-19 12:15:00 +0000138 int64_t last_rtp_timestamp = first_rtp_timestamp;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200139 int64_t last_log_timestamp = first_log_timestamp;
140 for (size_t i = 1; i < packets.size(); i++) {
141 if (packets[i].log_time_us() > end_time_us)
142 break;
143 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
144 last_log_timestamp = packets[i].log_time_us();
145 }
146 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
147 RTC_LOG(LS_WARNING)
148 << "Failed to estimate RTP clock frequency: Stream too short. ("
149 << packets.size() << " packets, "
150 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200151 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200152 }
153 double duration =
154 static_cast<double>(last_log_timestamp - first_log_timestamp) /
155 kNumMicrosecsPerSec;
156 double estimated_frequency =
157 (last_rtp_timestamp - first_rtp_timestamp) / duration;
158 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
159 if (std::fabs(estimated_frequency - f) < 0.05 * f) {
160 return f;
161 }
162 }
163 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
164 << estimated_frequency
165 << "not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200166 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700167}
168
tereliusdc35dcd2016-08-01 12:03:27 -0700169constexpr float kLeftMargin = 0.01f;
170constexpr float kRightMargin = 0.02f;
171constexpr float kBottomMargin = 0.02f;
172constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700173
Danil Chapovalov431abd92018-06-18 12:54:17 +0200174absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100175 const LoggedRtpPacketIncoming& old_packet,
176 const LoggedRtpPacketIncoming& new_packet) {
177 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
178 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700179 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100180 new_packet.rtp.header.extension.absoluteSendTime,
181 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200182 int64_t recv_time_diff =
183 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700184 double delay_change_us =
185 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100186 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700187 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200188 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700189 }
190}
191
Danil Chapovalov431abd92018-06-18 12:54:17 +0200192absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100193 const LoggedRtpPacketIncoming& old_packet,
194 const LoggedRtpPacketIncoming& new_packet,
195 const double sample_rate) {
196 int64_t send_time_diff =
197 WrappingDifference(new_packet.rtp.header.timestamp,
198 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200199 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700200
terelius53dc23c2017-03-13 05:24:05 -0700201 double delay_change =
202 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100203 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700204 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100205 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100206 RTC_LOG(LS_WARNING) << "Old capture time "
207 << old_packet.rtp.header.timestamp << ", received time "
208 << old_packet.log_time_us();
209 RTC_LOG(LS_WARNING) << "New capture time "
210 << new_packet.rtp.header.timestamp << ", received time "
211 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100212 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800213 << static_cast<double>(recv_time_diff) /
214 kNumMicrosecsPerSec
215 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100216 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100217 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100218 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700219 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100220 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700221}
222
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200223// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700224// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200225template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200226void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200227 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200228 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200229 TimeSeries* result) {
230 for (size_t i = 0; i < data_view.size(); i++) {
231 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200232 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200233 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700234 if (y)
235 result->points.emplace_back(x, *y);
236 }
237}
238
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200239// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700240// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
241// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200242template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700243void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200244 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200245 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
246 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200247 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700248 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700249 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200250 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200251 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700252 if (y)
253 result->points.emplace_back(x, static_cast<float>(*y));
254 }
255}
256
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200257// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700258// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
259// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200260template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700261void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200262 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200263 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
264 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200265 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700266 TimeSeries* result) {
267 ResultType sum = 0;
268 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200269 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200270 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100271 if (y) {
terelius53dc23c2017-03-13 05:24:05 -0700272 sum += *y;
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100273 result->points.emplace_back(x, static_cast<float>(sum));
274 }
tereliusccbbf8d2016-08-10 07:34:28 -0700275 }
276}
277
terelius6addf492016-08-23 17:34:07 -0700278// Calculates a moving average of |data| and stores the result in a TimeSeries.
279// A data point is generated every |step| microseconds from |begin_time|
280// to |end_time|. The value of each data point is the average of the data
281// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200282template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700283void MovingAverage(
Danil Chapovalov431abd92018-06-18 12:54:17 +0200284 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200285 const IterableType& data_view,
Bjorn Terelius068fc352019-02-13 22:38:25 +0100286 AnalyzerConfig config,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200287 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700288 size_t window_index_begin = 0;
289 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700290 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700291
Bjorn Terelius068fc352019-02-13 22:38:25 +0100292 for (int64_t t = config.begin_time_; t < config.end_time_ + config.step_;
293 t += config.step_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200294 while (window_index_end < data_view.size() &&
295 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200296 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700297 if (value)
298 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700299 ++window_index_end;
300 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200301 while (window_index_begin < data_view.size() &&
302 data_view[window_index_begin].log_time_us() <
Bjorn Terelius068fc352019-02-13 22:38:25 +0100303 t - config.window_duration_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200304 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700305 if (value)
306 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700307 ++window_index_begin;
308 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800309 float window_duration_s =
Bjorn Terelius068fc352019-02-13 22:38:25 +0100310 static_cast<float>(config.window_duration_) / kNumMicrosecsPerSec;
311 float x = config.GetCallTimeSec(t);
terelius53dc23c2017-03-13 05:24:05 -0700312 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700313 result->points.emplace_back(x, y);
314 }
315}
316
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100317template <typename T>
318TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
319 AnalyzerConfig config,
320 std::string rtcp_name,
321 int category_id) {
322 TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
323 for (const auto& rtcp : rtcp_list) {
324 float x = config.GetCallTimeSec(rtcp.log_time_us());
325 float y = category_id;
326 time_series.points.emplace_back(x, y);
327 }
328 return time_series;
329}
330
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800331const char kUnknownEnumValue[] = "unknown";
332
333const char kIceCandidateTypeLocal[] = "local";
334const char kIceCandidateTypeStun[] = "stun";
335const char kIceCandidateTypePrflx[] = "prflx";
336const char kIceCandidateTypeRelay[] = "relay";
337
338const char kProtocolUdp[] = "udp";
339const char kProtocolTcp[] = "tcp";
340const char kProtocolSsltcp[] = "ssltcp";
341const char kProtocolTls[] = "tls";
342
343const char kAddressFamilyIpv4[] = "ipv4";
344const char kAddressFamilyIpv6[] = "ipv6";
345
346const char kNetworkTypeEthernet[] = "ethernet";
347const char kNetworkTypeLoopback[] = "loopback";
348const char kNetworkTypeWifi[] = "wifi";
349const char kNetworkTypeVpn[] = "vpn";
350const char kNetworkTypeCellular[] = "cellular";
351
352std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
353 switch (type) {
354 case webrtc::IceCandidateType::kLocal:
355 return kIceCandidateTypeLocal;
356 case webrtc::IceCandidateType::kStun:
357 return kIceCandidateTypeStun;
358 case webrtc::IceCandidateType::kPrflx:
359 return kIceCandidateTypePrflx;
360 case webrtc::IceCandidateType::kRelay:
361 return kIceCandidateTypeRelay;
362 default:
363 return kUnknownEnumValue;
364 }
365}
366
367std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
368 switch (protocol) {
369 case webrtc::IceCandidatePairProtocol::kUdp:
370 return kProtocolUdp;
371 case webrtc::IceCandidatePairProtocol::kTcp:
372 return kProtocolTcp;
373 case webrtc::IceCandidatePairProtocol::kSsltcp:
374 return kProtocolSsltcp;
375 case webrtc::IceCandidatePairProtocol::kTls:
376 return kProtocolTls;
377 default:
378 return kUnknownEnumValue;
379 }
380}
381
382std::string GetAddressFamilyAsString(
383 webrtc::IceCandidatePairAddressFamily family) {
384 switch (family) {
385 case webrtc::IceCandidatePairAddressFamily::kIpv4:
386 return kAddressFamilyIpv4;
387 case webrtc::IceCandidatePairAddressFamily::kIpv6:
388 return kAddressFamilyIpv6;
389 default:
390 return kUnknownEnumValue;
391 }
392}
393
394std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
395 switch (type) {
396 case webrtc::IceCandidateNetworkType::kEthernet:
397 return kNetworkTypeEthernet;
398 case webrtc::IceCandidateNetworkType::kLoopback:
399 return kNetworkTypeLoopback;
400 case webrtc::IceCandidateNetworkType::kWifi:
401 return kNetworkTypeWifi;
402 case webrtc::IceCandidateNetworkType::kVpn:
403 return kNetworkTypeVpn;
404 case webrtc::IceCandidateNetworkType::kCellular:
405 return kNetworkTypeCellular;
406 default:
407 return kUnknownEnumValue;
408 }
409}
410
411std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200412 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800413 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
414 // represents a pair of a local server-reflexive candidate on a WiFi network
415 // and a remote relay candidate using TCP as the relay protocol on a cell
416 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200417 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800418 std::string local_candidate_type =
419 GetIceCandidateTypeAsString(config.local_candidate_type);
420 std::string remote_candidate_type =
421 GetIceCandidateTypeAsString(config.remote_candidate_type);
422 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
423 local_candidate_type +=
424 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
425 }
426 ss << local_candidate_type << ":"
427 << GetNetworkTypeAsString(config.local_network_type) << ":"
428 << GetAddressFamilyAsString(config.local_address_family) << "->"
429 << remote_candidate_type << ":"
430 << GetAddressFamilyAsString(config.remote_address_family) << "@"
431 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200432 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800433}
434
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200435std::string GetDirectionAsString(PacketDirection direction) {
436 if (direction == kIncomingPacket) {
437 return "Incoming";
438 } else {
439 return "Outgoing";
440 }
441}
442
443std::string GetDirectionAsShortString(PacketDirection direction) {
444 if (direction == kIncomingPacket) {
445 return "In";
446 } else {
447 return "Out";
448 }
449}
450
terelius54ce6802016-07-13 06:44:41 -0700451} // namespace
452
Sebastian Janssonb290a6d2019-01-03 14:46:23 +0100453EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200454 bool normalize_time)
Bjorn Terelius068fc352019-02-13 22:38:25 +0100455 : parsed_log_(log) {
456 config_.window_duration_ = 250000;
457 config_.step_ = 10000;
458 config_.normalize_time_ = normalize_time;
459 config_.begin_time_ = parsed_log_.first_timestamp();
460 config_.end_time_ = parsed_log_.last_timestamp();
461 if (config_.end_time_ < config_.begin_time_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200462 RTC_LOG(LS_WARNING) << "No useful events in the log.";
Bjorn Terelius068fc352019-02-13 22:38:25 +0100463 config_.begin_time_ = config_.end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000464 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200465
466 const auto& log_start_events = parsed_log_.start_log_events();
467 const auto& log_end_events = parsed_log_.stop_log_events();
468 auto start_iter = log_start_events.begin();
469 auto end_iter = log_end_events.begin();
470 while (start_iter != log_start_events.end()) {
471 int64_t start = start_iter->log_time_us();
472 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200473 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200474 if (start_iter != log_start_events.end())
475 next_start.emplace(start_iter->log_time_us());
476 if (end_iter != log_end_events.end() &&
477 end_iter->log_time_us() <=
478 next_start.value_or(std::numeric_limits<int64_t>::max())) {
479 int64_t end = end_iter->log_time_us();
480 RTC_DCHECK_LE(start, end);
481 log_segments_.push_back(std::make_pair(start, end));
482 ++end_iter;
483 } else {
484 // we're missing an end event. Assume that it occurred just before the
485 // next start.
486 log_segments_.push_back(
Bjorn Terelius068fc352019-02-13 22:38:25 +0100487 std::make_pair(start, next_start.value_or(config_.end_time_)));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200488 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700489 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100490 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200491 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700492}
493
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200494class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200495 public:
496 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
497
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200498 void Update(NetworkControlUpdate update) {
499 if (update.target_rate) {
500 last_bitrate_bps_ = update.target_rate->target_rate.bps();
501 bitrate_updated_ = true;
502 }
Stefan Holmer13181032016-07-29 14:48:54 +0200503 }
504
505 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
506 uint32_t bitrate) override {}
507
508 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
509 bool GetAndResetBitrateUpdated() {
510 bool bitrate_updated = bitrate_updated_;
511 bitrate_updated_ = false;
512 return bitrate_updated;
513 }
514
515 private:
516 uint32_t last_bitrate_bps_;
517 bool bitrate_updated_;
518};
519
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200520void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700521 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200522 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
523 // Filter on SSRC.
524 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700525 continue;
terelius54ce6802016-07-13 06:44:41 -0700526 }
terelius54ce6802016-07-13 06:44:41 -0700527
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200528 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
529 LineStyle::kBar);
530 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200531 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200532 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200533 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100534 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200535 };
536 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
537 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700538 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700539 }
540
Bjorn Terelius068fc352019-02-13 22:38:25 +0100541 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
542 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700543 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
544 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200545 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700546}
547
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100548void EventLogAnalyzer::CreateRtcpTypeGraph(PacketDirection direction,
549 Plot* plot) {
550 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
551 parsed_log_.transport_feedbacks(direction), config_, "TWCC", 1));
552 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
553 parsed_log_.receiver_reports(direction), config_, "RR", 2));
554 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
555 parsed_log_.sender_reports(direction), config_, "SR", 3));
556 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
557 parsed_log_.extended_reports(direction), config_, "XR", 4));
558 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.nacks(direction),
559 config_, "NACK", 5));
560 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.rembs(direction),
561 config_, "REMB", 6));
562 plot->AppendTimeSeries(
563 CreateRtcpTypeTimeSeries(parsed_log_.firs(direction), config_, "FIR", 7));
564 plot->AppendTimeSeries(
565 CreateRtcpTypeTimeSeries(parsed_log_.plis(direction), config_, "PLI", 8));
566 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
567 "Time (s)", kLeftMargin, kRightMargin);
568 plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
569 plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
570}
571
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200572template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700573void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700574 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200575 const IterableType& packets,
576 const std::string& label) {
577 TimeSeries time_series(label, LineStyle::kStep);
578 for (size_t i = 0; i < packets.size(); i++) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100579 float x = config_.GetCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200580 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700581 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200582 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700583}
584
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200585void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
586 Plot* plot) {
587 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
588 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
589 continue;
590 std::string label =
591 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
592 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
593 }
594 std::string label =
595 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
596 if (direction == kIncomingPacket) {
597 CreateAccumulatedPacketsTimeSeries(
598 plot, parsed_log_.incoming_rtcp_packets(), label);
599 } else {
600 CreateAccumulatedPacketsTimeSeries(
601 plot, parsed_log_.outgoing_rtcp_packets(), label);
602 }
philipelccd74892016-09-05 02:46:25 -0700603
Bjorn Terelius068fc352019-02-13 22:38:25 +0100604 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
605 "Time (s)", kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700606 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200607 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
608 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700609}
610
terelius54ce6802016-07-13 06:44:41 -0700611// For each SSRC, plot the time between the consecutive playouts.
612void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200613 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
614 uint32_t ssrc = playout_stream.first;
615 if (!MatchingSsrc(ssrc, desired_ssrc_))
616 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200617 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200618 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200619 for (const auto& playout_event : playout_stream.second) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100620 float x = config_.GetCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200621 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200622 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200623 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200624 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200625 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700626 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200627 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700628 }
629
Bjorn Terelius068fc352019-02-13 22:38:25 +0100630 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
631 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700632 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
633 kTopMargin);
634 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700635}
636
ivocaac9d6f2016-09-22 07:01:47 -0700637// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200638void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
639 Plot* plot) {
640 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
641 if (!IsAudioSsrc(direction, stream.ssrc))
642 continue;
643 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
644 LineStyle::kLine);
645 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700646 if (packet.header.extension.hasAudioLevel) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100647 float x = config_.GetCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700648 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
649 // Here we convert it to dBov.
650 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200651 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700652 }
653 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200654 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700655 }
656
Bjorn Terelius068fc352019-02-13 22:38:25 +0100657 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
658 "Time (s)", kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200659 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200660 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700661}
662
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100663// For each SSRC, plot the sequence number difference between consecutive
664// incoming packets.
terelius54ce6802016-07-13 06:44:41 -0700665void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200666 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
667 // Filter on SSRC.
668 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700669 continue;
terelius54ce6802016-07-13 06:44:41 -0700670 }
terelius54ce6802016-07-13 06:44:41 -0700671
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200672 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
673 LineStyle::kBar);
674 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
675 const LoggedRtpPacketIncoming& new_packet) {
676 int64_t diff =
677 WrappingDifference(new_packet.rtp.header.sequenceNumber,
678 old_packet.rtp.header.sequenceNumber, 1ul << 16);
679 return diff;
680 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200681 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100682 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200683 };
684 ProcessPairs<LoggedRtpPacketIncoming, float>(
685 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
686 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700687 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700688 }
689
Bjorn Terelius068fc352019-02-13 22:38:25 +0100690 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
691 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700692 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
693 kTopMargin);
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100694 plot->SetTitle("Incoming sequence number delta");
terelius54ce6802016-07-13 06:44:41 -0700695}
696
Stefan Holmer99f8e082016-09-09 13:37:50 +0200697void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200698 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
699 const std::vector<LoggedRtpPacketIncoming>& packets =
700 stream.incoming_packets;
701 // Filter on SSRC.
702 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200703 continue;
704 }
705
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200706 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
707 LineStyle::kLine, PointStyle::kHighlight);
708 // TODO(terelius): Should the window and step size be read from the class
709 // instead?
710 const int64_t kWindowUs = 1000000;
711 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100712 SeqNumUnwrapper<uint16_t> unwrapper_;
713 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800714 size_t window_index_begin = 0;
715 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200716 uint64_t highest_seq_number =
717 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
718 uint64_t highest_prior_seq_number =
719 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800720
Bjorn Terelius068fc352019-02-13 22:38:25 +0100721 for (int64_t t = config_.begin_time_; t < config_.end_time_ + kStep;
722 t += kStep) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200723 while (window_index_end < packets.size() &&
724 packets[window_index_end].rtp.log_time_us() < t) {
725 uint64_t sequence_number = unwrapper_.Unwrap(
726 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800727 highest_seq_number = std::max(highest_seq_number, sequence_number);
728 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200729 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200730 while (window_index_begin < packets.size() &&
731 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
732 uint64_t sequence_number = prior_unwrapper_.Unwrap(
733 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800734 highest_prior_seq_number =
735 std::max(highest_prior_seq_number, sequence_number);
736 ++window_index_begin;
737 }
Bjorn Terelius068fc352019-02-13 22:38:25 +0100738 float x = config_.GetCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200739 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800740 if (expected_packets > 0) {
741 int64_t received_packets = window_index_end - window_index_begin;
742 int64_t lost_packets = expected_packets - received_packets;
743 float y = static_cast<float>(lost_packets) / expected_packets * 100;
744 time_series.points.emplace_back(x, y);
745 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200746 }
philipel35ba9bd2017-04-19 05:58:51 -0700747 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200748 }
749
Bjorn Terelius068fc352019-02-13 22:38:25 +0100750 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
751 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100752 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
753 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
Stefan Holmer99f8e082016-09-09 13:37:50 +0200754}
755
terelius2ee076d2017-08-15 02:04:02 -0700756void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100757 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200758 // Filter on SSRC.
759 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200760 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700761 continue;
762 }
terelius54ce6802016-07-13 06:44:41 -0700763
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100764 const std::vector<LoggedRtpPacketIncoming>& packets =
765 stream.incoming_packets;
766 if (packets.size() < 100) {
767 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
768 << packets.size() << " packets in the stream.";
769 continue;
770 }
771 int64_t end_time_us = log_segments_.empty()
772 ? std::numeric_limits<int64_t>::max()
773 : log_segments_.front().second;
774 absl::optional<uint32_t> estimated_frequency =
775 EstimateRtpClockFrequency(packets, end_time_us);
776 if (!estimated_frequency)
777 continue;
778 const double frequency_hz = *estimated_frequency;
779 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
780 RTC_LOG(LS_WARNING)
781 << "Video stream should use a 90 kHz clock but appears to use "
782 << frequency_hz / 1000 << ". Discarding.";
783 continue;
784 }
785
786 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100787 return this->config_.GetCallTimeSec(packet.log_time_us());
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100788 };
789 auto ToNetworkDelay = [frequency_hz](
790 const LoggedRtpPacketIncoming& old_packet,
791 const LoggedRtpPacketIncoming& new_packet) {
792 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
793 };
794
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200795 TimeSeries capture_time_data(
796 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
797 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100798 AccumulatePairs<LoggedRtpPacketIncoming, double>(
799 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700800 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700801
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200802 TimeSeries send_time_data(
803 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
804 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100805 AccumulatePairs<LoggedRtpPacketIncoming, double>(
806 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
807 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700808 }
809
Bjorn Terelius068fc352019-02-13 22:38:25 +0100810 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
811 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +0100812 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
813 plot->SetTitle("Incoming network delay (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700814}
815
tereliusf736d232016-08-04 10:00:11 -0700816// Plot the fraction of packets lost (as perceived by the loss-based BWE).
817void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100818 TimeSeries time_series("Fraction lost", LineStyle::kLine,
819 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200820 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100821 float x = config_.GetCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200822 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700823 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700824 }
tereliusf736d232016-08-04 10:00:11 -0700825
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200826 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +0100827 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
828 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100829 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
830 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
tereliusf736d232016-08-04 10:00:11 -0700831}
832
terelius54ce6802016-07-13 06:44:41 -0700833// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200834void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
835 // TODO(terelius): This could be provided by the parser.
836 std::multimap<int64_t, size_t> packets_in_order;
837 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
838 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
839 packets_in_order.insert(
840 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700841 }
842
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200843 auto window_begin = packets_in_order.begin();
844 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700845 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700846
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800847 if (!packets_in_order.empty()) {
848 // Calculate a moving average of the bitrate and store in a TimeSeries.
849 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
850 for (int64_t time = config_.begin_time_;
851 time < config_.end_time_ + config_.step_; time += config_.step_) {
852 while (window_end != packets_in_order.end() && window_end->first < time) {
853 bytes_in_window += window_end->second;
854 ++window_end;
855 }
856 while (window_begin != packets_in_order.end() &&
857 window_begin->first < time - config_.window_duration_) {
858 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
859 bytes_in_window -= window_begin->second;
860 ++window_begin;
861 }
862 float window_duration_in_seconds =
863 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
864 float x = config_.GetCallTimeSec(time);
865 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
866 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700867 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800868 plot->AppendTimeSeries(std::move(bitrate_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200869 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200870
871 // Overlay the outgoing REMB over incoming bitrate.
872 TimeSeries remb_series("Remb", LineStyle::kStep);
873 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100874 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200875 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
876 remb_series.points.emplace_back(x, y);
877 }
878 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
879
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800880 if (!parsed_log_.generic_packets_received().empty()) {
881 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
882 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
883 return packet.packet_length * 8.0 / 1000.0;
884 };
885 MovingAverage<LoggedGenericPacketReceived, double>(
886 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
887 &time_series);
888 plot->AppendTimeSeries(std::move(time_series));
889 }
890
Bjorn Terelius068fc352019-02-13 22:38:25 +0100891 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
892 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200893 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
894 plot->SetTitle("Incoming RTP bitrate");
895}
896
897// Plot the total bandwidth used by all RTP streams.
898void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
899 bool show_detector_state,
900 bool show_alr_state) {
901 // TODO(terelius): This could be provided by the parser.
902 std::multimap<int64_t, size_t> packets_in_order;
903 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
904 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
905 packets_in_order.insert(
906 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
907 }
908
909 auto window_begin = packets_in_order.begin();
910 auto window_end = packets_in_order.begin();
911 size_t bytes_in_window = 0;
912
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800913 if (!packets_in_order.empty()) {
914 // Calculate a moving average of the bitrate and store in a TimeSeries.
915 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
916 for (int64_t time = config_.begin_time_;
917 time < config_.end_time_ + config_.step_; time += config_.step_) {
918 while (window_end != packets_in_order.end() && window_end->first < time) {
919 bytes_in_window += window_end->second;
920 ++window_end;
921 }
922 while (window_begin != packets_in_order.end() &&
923 window_begin->first < time - config_.window_duration_) {
924 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
925 bytes_in_window -= window_begin->second;
926 ++window_begin;
927 }
928 float window_duration_in_seconds =
929 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
930 float x = config_.GetCallTimeSec(time);
931 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
932 bitrate_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200933 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800934 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700935 }
936
terelius8058e582016-07-25 01:32:41 -0700937 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200938 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
939 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100940 float x = config_.GetCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200941 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
942 loss_series.points.emplace_back(x, y);
943 }
philipel10fc0e62017-04-11 01:50:23 -0700944
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200945 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
946 IntervalSeries overusing_series("Overusing", "#ff8e82",
947 IntervalSeries::kHorizontal);
948 IntervalSeries underusing_series("Underusing", "#5092fc",
949 IntervalSeries::kHorizontal);
950 IntervalSeries normal_series("Normal", "#c4ffc4",
951 IntervalSeries::kHorizontal);
952 IntervalSeries* last_series = &normal_series;
953 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700954
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200955 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700956
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200957 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100958 float x = config_.GetCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200959 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700960
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200961 if (last_detector_state != delay_update.detector_state) {
962 last_series->intervals.emplace_back(last_detector_switch, x);
963 last_detector_state = delay_update.detector_state;
964 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700965
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200966 switch (delay_update.detector_state) {
967 case BandwidthUsage::kBwNormal:
968 last_series = &normal_series;
969 break;
970 case BandwidthUsage::kBwUnderusing:
971 last_series = &underusing_series;
972 break;
973 case BandwidthUsage::kBwOverusing:
974 last_series = &overusing_series;
975 break;
976 case BandwidthUsage::kLast:
977 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200978 }
979 }
philipel23c7f252017-07-14 06:30:03 -0700980
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200981 delay_series.points.emplace_back(x, y);
982 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200983
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200984 RTC_CHECK(last_series);
Bjorn Terelius068fc352019-02-13 22:38:25 +0100985 last_series->intervals.emplace_back(last_detector_switch, config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200986
987 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
988 PointStyle::kHighlight);
989 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100990 float x = config_.GetCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200991 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
992 created_series.points.emplace_back(x, y);
993 }
994
995 TimeSeries result_series("Probing results.", LineStyle::kNone,
996 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200997 for (auto& result : parsed_log_.bwe_probe_success_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100998 float x = config_.GetCallTimeSec(result.log_time_us());
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200999 float y = static_cast<float>(result.bitrate_bps) / 1000;
1000 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001001 }
1002
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001003 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1004 PointStyle::kHighlight);
1005 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001006 float x = config_.GetCallTimeSec(failure.log_time_us());
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001007 probe_failures_series.points.emplace_back(x, 0);
1008 }
1009
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001010 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1011 bool previously_in_alr = false;
1012 int64_t alr_start = 0;
1013 for (auto& alr : parsed_log_.alr_state_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001014 float y = config_.GetCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001015 if (!previously_in_alr && alr.in_alr) {
1016 alr_start = alr.log_time_us();
1017 previously_in_alr = true;
1018 } else if (previously_in_alr && !alr.in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001019 float x = config_.GetCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +01001020 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001021 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +00001022 }
Björn Tereliusff612732018-04-25 14:23:01 +00001023 }
1024
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001025 if (previously_in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001026 float x = config_.GetCallTimeSec(alr_start);
1027 float y = config_.GetCallTimeSec(config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001028 alr_state.intervals.emplace_back(x, y);
1029 }
1030
1031 if (show_detector_state) {
1032 plot->AppendIntervalSeries(std::move(overusing_series));
1033 plot->AppendIntervalSeries(std::move(underusing_series));
1034 plot->AppendIntervalSeries(std::move(normal_series));
1035 }
1036
1037 if (show_alr_state) {
1038 plot->AppendIntervalSeries(std::move(alr_state));
1039 }
1040 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001041 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001042 plot->AppendTimeSeries(std::move(delay_series));
1043 plot->AppendTimeSeries(std::move(created_series));
1044 plot->AppendTimeSeries(std::move(result_series));
1045
1046 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001047 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001048 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001049 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001050 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001051 remb_series.points.emplace_back(x, y);
1052 }
1053 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1054
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001055 if (!parsed_log_.generic_packets_sent().empty()) {
1056 {
1057 TimeSeries time_series("Outgoing generic total bitrate",
1058 LineStyle::kLine);
1059 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1060 return packet.packet_length() * 8.0 / 1000.0;
1061 };
1062 MovingAverage<LoggedGenericPacketSent, double>(
1063 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1064 &time_series);
1065 plot->AppendTimeSeries(std::move(time_series));
1066 }
1067
1068 {
1069 TimeSeries time_series("Outgoing generic payload bitrate",
1070 LineStyle::kLine);
1071 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1072 return packet.payload_length * 8.0 / 1000.0;
1073 };
1074 MovingAverage<LoggedGenericPacketSent, double>(
1075 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1076 &time_series);
1077 plot->AppendTimeSeries(std::move(time_series));
1078 }
1079 }
1080
Bjorn Terelius068fc352019-02-13 22:38:25 +01001081 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1082 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001083 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001084 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001085}
1086
1087// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001088void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1089 Plot* plot) {
1090 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1091 // Filter on SSRC.
1092 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001093 continue;
terelius54ce6802016-07-13 06:44:41 -07001094 }
1095
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001096 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1097 LineStyle::kLine);
1098 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1099 return packet.total_length * 8.0 / 1000.0;
1100 };
terelius53dc23c2017-03-13 05:24:05 -07001101 MovingAverage<LoggedRtpPacket, double>(
Bjorn Terelius068fc352019-02-13 22:38:25 +01001102 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001103 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001104 }
1105
Bjorn Terelius068fc352019-02-13 22:38:25 +01001106 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1107 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001108 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001109 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001110}
1111
Bjorn Terelius9775a582019-02-15 17:29:58 +01001112// Plot the bitrate allocation for each temporal and spatial layer.
1113// Computed from RTCP XR target bitrate block, so the graph is only populated if
1114// those are sent.
1115void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1116 Plot* plot) {
1117 std::map<LayerDescription, TimeSeries> time_series;
1118 const auto& xr_list = parsed_log_.extended_reports(direction);
1119 for (const auto& rtcp : xr_list) {
1120 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1121 rtcp.xr.target_bitrate();
1122 if (!target_bitrate.has_value())
1123 continue;
1124 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1125 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1126 bitrate_item.temporal_layer);
1127 auto time_series_it = time_series.find(layer);
1128 if (time_series_it == time_series.end()) {
1129 std::string layer_name = GetLayerName(layer);
1130 bool inserted;
1131 std::tie(time_series_it, inserted) = time_series.insert(
1132 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1133 RTC_DCHECK(inserted);
1134 }
1135 float x = config_.GetCallTimeSec(rtcp.log_time_us());
1136 float y = bitrate_item.target_bitrate_kbps;
1137 time_series_it->second.points.emplace_back(x, y);
1138 }
1139 }
1140 for (auto& layer : time_series) {
1141 plot->AppendTimeSeries(std::move(layer.second));
1142 }
1143 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1144 "Time (s)", kLeftMargin, kRightMargin);
1145 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1146 if (direction == kIncomingPacket)
1147 plot->SetTitle("Target bitrate per incoming layer");
1148 else
1149 plot->SetTitle("Target bitrate per outgoing layer");
1150}
1151
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001152void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1153 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1154 PointStyle::kHighlight);
1155 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1156 PointStyle::kHighlight);
1157 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1158 PointStyle::kHighlight);
1159 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1160 PointStyle::kHighlight);
1161
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001162 LogBasedNetworkControllerSimulation simulation(
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001163 absl::make_unique<GoogCcNetworkControllerFactory>(),
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001164 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1165 if (update.target_rate) {
1166 target_rates.points.emplace_back(
1167 config_.GetCallTimeSec(at_time.us()),
1168 update.target_rate->target_rate.kbps<float>());
1169 }
1170 });
1171
1172 simulation.ProcessEventsInLog(parsed_log_);
1173 for (const auto& logged : parsed_log_.bwe_delay_updates())
1174 delay_based.points.emplace_back(
1175 config_.GetCallTimeSec(logged.log_time_us()),
1176 logged.bitrate_bps / 1000);
1177 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1178 probe_results.points.emplace_back(
1179 config_.GetCallTimeSec(logged.log_time_us()),
1180 logged.bitrate_bps / 1000);
1181 for (const auto& logged : parsed_log_.bwe_loss_updates())
1182 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time_us()),
1183 logged.bitrate_bps / 1000);
1184
1185 plot->AppendTimeSeries(std::move(delay_based));
1186 plot->AppendTimeSeries(std::move(loss_based));
1187 plot->AppendTimeSeries(std::move(probe_results));
1188 plot->AppendTimeSeries(std::move(target_rates));
1189
1190 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1191 "Time (s)", kLeftMargin, kRightMargin);
1192 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1193 plot->SetTitle("Simulated BWE behavior");
1194}
1195
Bjorn Terelius28db2662017-10-04 14:22:43 +02001196void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001197 using RtpPacketType = LoggedRtpPacketOutgoing;
1198 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001199
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001200 // TODO(terelius): This could be provided by the parser.
1201 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1202 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1203 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1204 outgoing_rtp.insert(
1205 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001206 }
1207
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001208 const std::vector<TransportFeedbackType>& incoming_rtcp =
1209 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001210
1211 SimulatedClock clock(0);
1212 BitrateObserver observer;
1213 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001214 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001215 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001216 TransportFeedbackAdapter transport_feedback;
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001217 auto factory = GoogCcNetworkControllerFactory();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001218 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001219 // TODO(holmer): Log the call config and use that here instead.
1220 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001221 NetworkControllerConfig cc_config;
Sebastian Jansson78416b62018-10-18 13:08:17 +02001222 cc_config.constraints.at_time = Timestamp::us(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001223 cc_config.constraints.starting_rate = DataRate::bps(kDefaultStartBitrateBps);
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001224 cc_config.event_log = &null_event_log;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001225 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001226
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001227 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1228 PointStyle::kHighlight);
1229 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1230 PointStyle::kHighlight);
1231 TimeSeries acked_estimate_time_series(
1232 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001233
1234 auto rtp_iterator = outgoing_rtp.begin();
1235 auto rtcp_iterator = incoming_rtcp.begin();
1236
1237 auto NextRtpTime = [&]() {
1238 if (rtp_iterator != outgoing_rtp.end())
1239 return static_cast<int64_t>(rtp_iterator->first);
1240 return std::numeric_limits<int64_t>::max();
1241 };
1242
1243 auto NextRtcpTime = [&]() {
1244 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001245 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001246 return std::numeric_limits<int64_t>::max();
1247 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001248 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001249
1250 auto NextProcessTime = [&]() {
1251 if (rtcp_iterator != incoming_rtcp.end() ||
1252 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001253 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001254 }
1255 return std::numeric_limits<int64_t>::max();
1256 };
1257
Stefan Holmer492ee282016-10-27 17:19:20 +02001258 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001259#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001260 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001261 // The event_log_visualizer should normally not be compiled with
1262 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1263 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1264 // and piping the output to plot_dynamics.py can be used as a hack to get the
1265 // internal state of various BWE components. In this case, it is important
1266 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
Sebastian Jansson4ad51d82019-06-11 11:24:40 +02001267 // GoogCcNetworkController since that would lead to duplicate outputs.
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001268 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Sebastian Jansson95edb032019-01-17 16:24:12 +01001269 &field_trial_config_,
1270 absl::make_unique<BitrateEstimator>(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001271#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001272 int64_t time_us =
1273 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001274 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001275 while (time_us != std::numeric_limits<int64_t>::max()) {
1276 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001277 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1278 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1279 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1280 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1281 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
Erik Språng30a276b2019-04-23 12:00:11 +02001282 RtpPacketSendInfo packet_info;
1283 packet_info.ssrc = rtp_packet.rtp.header.ssrc;
Bjorn Tereliusf2e9cab2019-05-27 16:44:09 +02001284 packet_info.transport_sequence_number =
Erik Språng30a276b2019-04-23 12:00:11 +02001285 rtp_packet.rtp.header.extension.transportSequenceNumber;
1286 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
1287 packet_info.has_rtp_sequence_number = true;
1288 packet_info.length = rtp_packet.rtp.total_length;
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001289 transport_feedback.AddPacket(
Erik Språng30a276b2019-04-23 12:00:11 +02001290 packet_info,
1291 0u, // Per packet overhead bytes.
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001292 Timestamp::us(rtp_packet.rtp.log_time_us()));
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001293 rtc::SentPacket sent_packet(
1294 rtp_packet.rtp.header.extension.transportSequenceNumber,
1295 rtp_packet.rtp.log_time_us() / 1000);
1296 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1297 if (sent_msg)
1298 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1299 }
1300 ++rtp_iterator;
1301 }
Stefan Holmer13181032016-07-29 14:48:54 +02001302 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001303 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001304
1305 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001306 rtcp_iterator->transport_feedback,
1307 Timestamp::ms(clock.TimeInMilliseconds()));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001308 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001309 if (feedback_msg) {
1310 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001311 std::vector<PacketResult> feedback =
1312 feedback_msg->SortedByReceiveTime();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001313 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001314#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001315 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001316#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001317 for (const PacketResult& packet : feedback)
1318 acked_bitrate.Update(packet.sent_packet.size.bytes(),
1319 packet.receive_time.ms());
1320 bitrate_bps = acked_bitrate.Rate(feedback.back().receive_time.ms());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001321 }
Stefan Holmer13181032016-07-29 14:48:54 +02001322 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001323
Bjorn Terelius068fc352019-02-13 22:38:25 +01001324 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001325 float y = bitrate_bps.value_or(0) / 1000;
1326 acked_time_series.points.emplace_back(x, y);
1327#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001328 y = acknowledged_bitrate_estimator.bitrate()
1329 .value_or(DataRate::Zero())
1330 .kbps();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001331 acked_estimate_time_series.points.emplace_back(x, y);
1332#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001333 ++rtcp_iterator;
1334 }
stefanc3de0332016-08-02 07:22:17 -07001335 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1336 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001337 ProcessInterval msg;
1338 msg.at_time = Timestamp::us(clock.TimeInMicroseconds());
1339 observer.Update(goog_cc->OnProcessInterval(msg));
1340 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001341 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001342 if (observer.GetAndResetBitrateUpdated() ||
1343 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001344 uint32_t y = observer.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001345 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001346 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001347 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001348 }
1349 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1350 }
1351 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001352 plot->AppendTimeSeries(std::move(time_series));
1353 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001354 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001355
Bjorn Terelius068fc352019-02-13 22:38:25 +01001356 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1357 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001358 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001359 plot->SetTitle("Simulated send-side BWE behavior");
1360}
1361
1362void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001363 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001364 class RembInterceptingPacketRouter : public PacketRouter {
1365 public:
1366 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1367 uint32_t bitrate_bps) override {
1368 last_bitrate_bps_ = bitrate_bps;
1369 bitrate_updated_ = true;
1370 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1371 }
1372 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1373 bool GetAndResetBitrateUpdated() {
1374 bool bitrate_updated = bitrate_updated_;
1375 bitrate_updated_ = false;
1376 return bitrate_updated;
1377 }
1378
1379 private:
1380 uint32_t last_bitrate_bps_;
1381 bool bitrate_updated_;
1382 };
1383
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001384 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001385
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001386 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1387 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1388 for (const auto& rtp_packet : stream.incoming_packets)
1389 incoming_rtp.insert(
1390 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001391 }
1392 }
1393
1394 SimulatedClock clock(0);
1395 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001396 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001397 // Is this intentional?
1398 ReceiveSideCongestionController rscc(&clock, &packet_router);
1399 // TODO(holmer): Log the call config and use that here instead.
1400 // static const uint32_t kDefaultStartBitrateBps = 300000;
1401 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1402
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001403 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1404 PointStyle::kHighlight);
1405 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001406
1407 RateStatistics acked_bitrate(250, 8000);
1408 int64_t last_update_us = 0;
1409 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001410 const RtpPacketType& packet = *kv.second;
1411 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1412 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1413 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001414 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001415 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001416 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001417 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001418 if (bitrate_bps) {
1419 uint32_t y = *bitrate_bps / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001420 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001421 acked_time_series.points.emplace_back(x, y);
1422 }
1423 if (packet_router.GetAndResetBitrateUpdated() ||
1424 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1425 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001426 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001427 time_series.points.emplace_back(x, y);
1428 last_update_us = clock.TimeInMicroseconds();
1429 }
1430 }
1431 // Add the data set to the plot.
1432 plot->AppendTimeSeries(std::move(time_series));
1433 plot->AppendTimeSeries(std::move(acked_time_series));
1434
Bjorn Terelius068fc352019-02-13 22:38:25 +01001435 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1436 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001437 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1438 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001439}
1440
tereliuse34c19c2016-08-15 08:47:14 -07001441void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001442 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1443 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001444 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001445 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001446 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1447 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001448
stefana0a8ed72017-09-06 02:06:32 -07001449 int64_t prev_y = 0;
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001450 for (auto packet : GetNetworkTrace(parsed_log_)) {
1451 if (packet.arrival_time_ms == PacketFeedback::kNotReceived)
1452 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001453 float x = config_.GetCallTimeSec(1000 * packet.feedback_arrival_time_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001454 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1455 late_feedback_series.points.emplace_back(x, prev_y);
1456 continue;
stefanc3de0332016-08-02 07:22:17 -07001457 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001458 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1459 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001460 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1461 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1462 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001463 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001464 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001465
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001466 // We assume that the base network delay (w/o queues) is equal to half
1467 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1468 // observed 1-ways delay and add half the minumum RTT.
1469 const int64_t estimated_clock_offset_ms =
1470 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001471 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001472 point.y -= estimated_clock_offset_ms;
stefana0a8ed72017-09-06 02:06:32 -07001473 for (TimeSeriesPoint& point : late_feedback_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001474 point.y -= estimated_clock_offset_ms;
1475
stefanc3de0332016-08-02 07:22:17 -07001476 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001477 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1478 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001479
Bjorn Terelius068fc352019-02-13 22:38:25 +01001480 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1481 "Time (s)", kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001482 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +01001483 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001484}
stefan08383272016-12-20 08:51:52 -08001485
Bjorn Terelius0295a962017-10-25 17:42:41 +02001486void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001487 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1488 const std::vector<LoggedRtpPacketOutgoing>& packets =
1489 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001490
Konrad Hofbauerbfb735b2019-04-16 11:12:11 +02001491 if (IsRtxSsrc(kOutgoingPacket, stream.ssrc)) {
1492 continue;
1493 }
1494
Bjorn Terelius0295a962017-10-25 17:42:41 +02001495 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001496 RTC_LOG(LS_WARNING)
1497 << "Can't estimate a the RTP clock frequency or the "
1498 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001499 continue;
1500 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001501 int64_t end_time_us = log_segments_.empty()
1502 ? std::numeric_limits<int64_t>::max()
1503 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001504 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001505 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001506 if (!estimated_frequency)
1507 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001508 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1509 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001510 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001511 << "Video stream should use a 90 kHz clock but appears to use "
1512 << *estimated_frequency / 1000 << ". Discarding.";
1513 continue;
1514 }
1515
1516 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001517 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001518 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001519 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001520 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1521 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001522 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1523 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1524 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001525 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001526 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001527 first_capture_timestamp) /
1528 *estimated_frequency * 1000;
1529 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001530 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1531 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001532 float x = config_.GetCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001533 float y = send_time_ms - capture_time_ms;
1534 pacer_delay_series.points.emplace_back(x, y);
1535 }
1536 plot->AppendTimeSeries(std::move(pacer_delay_series));
1537 }
1538
Bjorn Terelius068fc352019-02-13 22:38:25 +01001539 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1540 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001541 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1542 plot->SetTitle(
1543 "Delay from capture to send time. (First packet normalized to 0.)");
1544}
1545
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001546void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1547 Plot* plot) {
1548 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1549 TimeSeries rtp_timestamps(
1550 GetStreamName(direction, stream.ssrc) + " capture-time",
1551 LineStyle::kLine, PointStyle::kHighlight);
1552 for (const auto& packet : stream.packet_view) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001553 float x = config_.GetCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001554 float y = packet.header.timestamp;
1555 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001556 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001557 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001558
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001559 TimeSeries rtcp_timestamps(
1560 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1561 LineStyle::kLine, PointStyle::kHighlight);
1562 // TODO(terelius): Why only sender reports?
1563 const auto& sender_reports = parsed_log_.sender_reports(direction);
1564 for (const auto& rtcp : sender_reports) {
1565 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1566 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001567 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001568 float y = rtcp.sr.rtp_timestamp();
1569 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001570 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001571 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001572 }
1573
Bjorn Terelius068fc352019-02-13 22:38:25 +01001574 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1575 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001576 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1577 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001578}
michaelt6e5b2192017-02-22 07:33:27 -08001579
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001580void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1581 PacketDirection direction,
1582 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1583 std::string title,
1584 std::string yaxis_label,
1585 Plot* plot) {
1586 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1587 const auto& sender_reports = parsed_log_.sender_reports(direction);
1588 for (const auto& rtcp : sender_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001589 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001590 uint32_t ssrc = rtcp.sr.sender_ssrc();
1591 for (const auto& block : rtcp.sr.report_blocks()) {
1592 float y = fy(block);
1593 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1594 bool inserted;
1595 if (sr_report_it == sr_reports_by_ssrc.end()) {
1596 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1597 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1598 LineStyle::kLine, PointStyle::kHighlight));
1599 }
1600 sr_report_it->second.points.emplace_back(x, y);
1601 }
1602 }
1603 for (auto& kv : sr_reports_by_ssrc) {
1604 plot->AppendTimeSeries(std::move(kv.second));
1605 }
1606
1607 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1608 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1609 for (const auto& rtcp : receiver_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001610 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001611 uint32_t ssrc = rtcp.rr.sender_ssrc();
1612 for (const auto& block : rtcp.rr.report_blocks()) {
1613 float y = fy(block);
1614 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1615 bool inserted;
1616 if (rr_report_it == rr_reports_by_ssrc.end()) {
1617 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1618 ssrc,
1619 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1620 LineStyle::kLine, PointStyle::kHighlight));
1621 }
1622 rr_report_it->second.points.emplace_back(x, y);
1623 }
1624 }
1625 for (auto& kv : rr_reports_by_ssrc) {
1626 plot->AppendTimeSeries(std::move(kv.second));
1627 }
1628
Bjorn Terelius068fc352019-02-13 22:38:25 +01001629 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1630 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001631 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1632 plot->SetTitle(title);
1633}
1634
michaelt6e5b2192017-02-22 07:33:27 -08001635void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001636 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1637 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001638 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001639 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001640 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001641 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001642 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001643 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001644 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001645 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001646 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001647 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001648 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001649 ToCallTime, GetAnaBitrateBps,
1650 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001651 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001652 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1653 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001654 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1655 plot->SetTitle("Reported audio encoder target bitrate");
1656}
1657
1658void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001659 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1660 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001661 auto GetAnaFrameLengthMs =
1662 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001663 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001664 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001665 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001666 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001667 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001668 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001669 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001670 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001671 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001672 ToCallTime, GetAnaFrameLengthMs,
1673 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001674 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001675 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1676 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001677 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1678 plot->SetTitle("Reported audio encoder frame length");
1679}
1680
terelius2ee076d2017-08-15 02:04:02 -07001681void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001682 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001683 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001684 auto GetAnaPacketLoss =
1685 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001686 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001687 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001688 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001689 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001690 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001691 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001692 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001693 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001694 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001695 ToCallTime, GetAnaPacketLoss,
1696 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001697 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001698 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1699 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001700 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1701 kTopMargin);
1702 plot->SetTitle("Reported audio encoder lost packets");
1703}
1704
1705void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001706 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1707 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001708 auto GetAnaFecEnabled =
1709 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001710 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001711 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001712 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001713 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001714 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001715 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001716 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001717 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001718 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001719 ToCallTime, GetAnaFecEnabled,
1720 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001721 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001722 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1723 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001724 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1725 plot->SetTitle("Reported audio encoder FEC");
1726}
1727
1728void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001729 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1730 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001731 auto GetAnaDtxEnabled =
1732 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001733 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001734 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001735 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001736 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001737 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001738 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001739 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001740 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001741 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001742 ToCallTime, GetAnaDtxEnabled,
1743 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001744 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001745 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1746 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001747 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1748 plot->SetTitle("Reported audio encoder DTX");
1749}
1750
1751void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001752 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1753 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001754 auto GetAnaNumChannels =
1755 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001756 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001757 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001758 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001759 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001760 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001761 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001762 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001763 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001764 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001765 ToCallTime, GetAnaNumChannels,
1766 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001767 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001768 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1769 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001770 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1771 kBottomMargin, kTopMargin);
1772 plot->SetTitle("Reported audio encoder number of channels");
1773}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001774
1775class NetEqStreamInput : public test::NetEqInput {
1776 public:
1777 // Does not take any ownership, and all pointers must refer to valid objects
1778 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001779 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001780 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001781 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001782 : packet_stream_(*packet_stream),
1783 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001784 output_events_it_(output_events->begin()),
1785 output_events_end_(output_events->end()),
1786 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001787 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001788 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001789 }
1790
Danil Chapovalov431abd92018-06-18 12:54:17 +02001791 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001792 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001793 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001794 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001795 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001796 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001797 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001798 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001799 }
1800
Danil Chapovalov431abd92018-06-18 12:54:17 +02001801 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001802 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001803 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001804 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001805 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001806 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001807 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001808 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001809 }
1810
1811 std::unique_ptr<PacketData> PopPacket() override {
1812 if (packet_stream_it_ == packet_stream_.end()) {
1813 return std::unique_ptr<PacketData>();
1814 }
1815 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001816 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001817 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001818
1819 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1820 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001821 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1822 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001823 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1824
1825 ++packet_stream_it_;
1826 return packet_data;
1827 }
1828
1829 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001830 if (output_events_it_ != output_events_end_) {
1831 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001832 }
1833 }
1834
1835 bool ended() const override { return !NextEventTime(); }
1836
Danil Chapovalov431abd92018-06-18 12:54:17 +02001837 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001838 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001839 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001840 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001841 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001842 }
1843
1844 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001845 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1846 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001847 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1848 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001849 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001850};
1851
1852namespace {
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001853
1854// Factory to create a "replacement decoder" that produces the decoded audio
1855// by reading from a file rather than from the encoded payloads.
1856class ReplacementAudioDecoderFactory : public AudioDecoderFactory {
1857 public:
1858 ReplacementAudioDecoderFactory(const absl::string_view replacement_file_name,
1859 int file_sample_rate_hz)
1860 : replacement_file_name_(replacement_file_name),
1861 file_sample_rate_hz_(file_sample_rate_hz) {}
1862
1863 std::vector<AudioCodecSpec> GetSupportedDecoders() override {
1864 RTC_NOTREACHED();
1865 return {};
1866 }
1867
1868 bool IsSupportedDecoder(const SdpAudioFormat& format) override {
1869 return true;
1870 }
1871
1872 std::unique_ptr<AudioDecoder> MakeAudioDecoder(
1873 const SdpAudioFormat& format,
1874 absl::optional<AudioCodecPairId> codec_pair_id) override {
1875 auto replacement_file = absl::make_unique<test::ResampleInputAudioFile>(
1876 replacement_file_name_, file_sample_rate_hz_);
1877 replacement_file->set_output_rate_hz(48000);
1878 return absl::make_unique<test::FakeDecodeFromFile>(
1879 std::move(replacement_file), 48000, false);
1880 }
1881
1882 private:
1883 const std::string replacement_file_name_;
1884 const int file_sample_rate_hz_;
1885};
1886
henrik.lundin3c938fc2017-06-14 06:09:58 -07001887// Creates a NetEq test object and all necessary input and output helpers. Runs
1888// the test and returns the NetEqDelayAnalyzer object that was used to
1889// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001890std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001891 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001892 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001893 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001894 const std::string& replacement_file_name,
1895 int file_sample_rate_hz) {
1896 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001897 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001898
1899 constexpr int kReplacementPt = 127;
1900 std::set<uint8_t> cn_types;
1901 std::set<uint8_t> forbidden_types;
1902 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1903 cn_types, forbidden_types));
1904
1905 NetEq::Config config;
1906 config.max_packets_in_buffer = 200;
1907 config.enable_fast_accelerate = true;
1908
1909 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1910
Niels Möller3f651d82018-12-19 15:06:17 +01001911 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001912 new rtc::RefCountedObject<ReplacementAudioDecoderFactory>(
1913 replacement_file_name, file_sample_rate_hz);
Niels Möller3f651d82018-12-19 15:06:17 +01001914
Niels Möller05543682019-01-10 16:55:06 +01001915 test::NetEqTest::DecoderMap codecs = {
1916 {kReplacementPt, SdpAudioFormat("l16", 48000, 1)}};
henrik.lundin3c938fc2017-06-14 06:09:58 -07001917
1918 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1919 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001920 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1921 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001922 test::DefaultNetEqTestErrorCallback error_cb;
1923 test::NetEqTest::Callbacks callbacks;
1924 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001925 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1926 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001927
Niels Möllerbd6dee82019-01-02 09:39:47 +01001928 test::NetEqTest test(config, decoder_factory, codecs, nullptr,
Niels Möller3f651d82018-12-19 15:06:17 +01001929 std::move(input), std::move(output), callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001930 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001931 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001932}
1933} // namespace
1934
Minyue Lic6ff7572018-05-04 09:46:44 +02001935EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001936 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001937 int file_sample_rate_hz) const {
1938 NetEqStatsGetterMap neteq_stats;
1939
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001940 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001941 const uint32_t ssrc = stream.ssrc;
1942 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1943 continue;
1944 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1945 &stream.incoming_packets;
1946 if (audio_packets == nullptr) {
1947 // No incoming audio stream found.
1948 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001949 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001950
Minyue Li27e2b7d2018-05-07 15:20:24 +02001951 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1952
1953 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1954 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1955 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1956 // Could not find output events with SSRC matching the input audio stream.
1957 // Using the first available stream of output events.
1958 output_events_it = parsed_log_.audio_playout_events().cbegin();
1959 }
1960
Danil Chapovalov431abd92018-06-18 12:54:17 +02001961 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001962 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001963 ? absl::nullopt
1964 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001965
1966 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1967 audio_packets, &output_events_it->second, end_time_ms,
1968 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001969 }
1970
Minyue Lic6ff7572018-05-04 09:46:44 +02001971 return neteq_stats;
1972}
1973
Minyue Lic97933f2018-08-10 12:51:15 +02001974// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1975// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001976void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001977 uint32_t ssrc,
1978 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001979 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001980 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1981 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1982 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1983 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1984
Minyue Li01d2a672018-06-21 21:17:19 +02001985 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001986 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1987 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001988
Minyue Lic97933f2018-08-10 12:51:15 +02001989 TimeSeries time_series_packet_arrival("packet arrival delay",
1990 LineStyle::kLine);
1991 TimeSeries time_series_relative_packet_arrival(
1992 "Relative packet arrival delay", LineStyle::kLine);
1993 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
1994 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
1995 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02001996
1997 for (const auto& data : arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001998 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02001999 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002000 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002001 }
2002 for (const auto& data : corrected_arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002003 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002004 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002005 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02002006 TimeSeriesPoint(x, y));
2007 }
2008 for (const auto& data : playout_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002009 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002010 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002011 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002012 }
2013 for (const auto& data : target_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002014 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002015 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002016 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002017 }
2018
Minyue Lic97933f2018-08-10 12:51:15 +02002019 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
2020 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
2021 plot->AppendTimeSeries(std::move(time_series_play_time));
2022 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002023
Bjorn Terelius068fc352019-02-13 22:38:25 +01002024 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2025 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002026 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
2027 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002028 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
2029}
2030
Minyue Lic9ac93f2018-06-26 13:01:32 +02002031template <typename NetEqStatsType>
2032void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02002033 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02002034 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
2035 const test::NetEqStatsGetter*)> data_extractor,
2036 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02002037 const std::string& plot_name,
2038 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02002039 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02002040
2041 for (const auto& st : neteq_stats) {
2042 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02002043 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
2044 data_extractor(st.second.get());
2045 for (const auto& data : *data_vector) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002046 const float time =
2047 config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Lic9ac93f2018-06-26 13:01:32 +02002048 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002049 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02002050 }
2051 }
2052
2053 for (auto& series : time_series) {
2054 series.second.label = GetStreamName(kIncomingPacket, series.first);
2055 series.second.line_style = LineStyle::kLine;
2056 plot->AppendTimeSeries(std::move(series.second));
2057 }
2058
Bjorn Terelius068fc352019-02-13 22:38:25 +01002059 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2060 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002061 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002062 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002063}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002064
Minyue Lic9ac93f2018-06-26 13:01:32 +02002065void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
2066 const NetEqStatsGetterMap& neteq_stats,
2067 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
2068 const std::string& plot_name,
2069 Plot* plot) const {
2070 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
2071 neteq_stats,
2072 [](const test::NetEqStatsGetter* stats_getter) {
2073 return stats_getter->stats();
2074 },
2075 stats_extractor, plot_name, plot);
2076}
2077
2078void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
2079 const NetEqStatsGetterMap& neteq_stats,
2080 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
2081 const std::string& plot_name,
2082 Plot* plot) const {
2083 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
2084 neteq_stats,
2085 [](const test::NetEqStatsGetter* stats_getter) {
2086 return stats_getter->lifetime_stats();
2087 },
2088 stats_extractor, plot_name, plot);
2089}
2090
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002091void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
2092 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002093 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002094 if (configs_by_cp_id.find(config.candidate_pair_id) ==
2095 configs_by_cp_id.end()) {
2096 const std::string candidate_pair_desc =
2097 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08002098 configs_by_cp_id[config.candidate_pair_id] =
2099 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
2100 candidate_pair_desc,
2101 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002102 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2103 candidate_pair_desc;
2104 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002105 float x = config_.GetCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002106 float y = static_cast<float>(config.type);
2107 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
2108 }
2109
2110 // TODO(qingsi): There can be a large number of candidate pairs generated by
2111 // certain calls and the frontend cannot render the chart in this case due to
2112 // the failure of generating a palette with the same number of colors.
2113 for (auto& kv : configs_by_cp_id) {
2114 plot->AppendTimeSeries(std::move(kv.second));
2115 }
2116
Bjorn Terelius068fc352019-02-13 22:38:25 +01002117 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2118 "Time (s)", kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002119 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
2120 kTopMargin);
2121 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
2122}
2123
2124std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
2125 uint32_t candidate_pair_id) {
2126 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
2127 candidate_pair_desc_by_id_.end()) {
2128 return candidate_pair_desc_by_id_[candidate_pair_id];
2129 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002130 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002131 // TODO(qingsi): Add the handling of the "Updated" config event after the
2132 // visualization of property change for candidate pairs is introduced.
2133 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
2134 candidate_pair_desc_by_id_.end()) {
2135 const std::string candidate_pair_desc =
2136 GetCandidatePairLogDescriptionAsString(config);
2137 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2138 candidate_pair_desc;
2139 }
2140 }
2141 return candidate_pair_desc_by_id_[candidate_pair_id];
2142}
2143
2144void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
2145 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002146 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002147 if (checks_by_cp_id.find(event.candidate_pair_id) ==
2148 checks_by_cp_id.end()) {
2149 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08002150 "[" + std::to_string(event.candidate_pair_id) + "]" +
2151 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002152 LineStyle::kNone, PointStyle::kHighlight);
2153 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002154 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein6353fbc2018-12-03 14:35:59 -08002155 constexpr int kIceCandidatePairEventTypeOffset =
2156 static_cast<int>(IceCandidatePairConfigType::kNumValues);
2157 float y = static_cast<float>(event.type) + kIceCandidatePairEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002158 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2159 }
2160
2161 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2162 for (auto& kv : checks_by_cp_id) {
2163 plot->AppendTimeSeries(std::move(kv.second));
2164 }
2165
Bjorn Terelius068fc352019-02-13 22:38:25 +01002166 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2167 "Time (s)", kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002168 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
2169 kTopMargin);
2170 plot->SetTitle("[IceEventLog] ICE connectivity checks");
2171}
2172
Zach Stein10a58012018-12-07 12:26:28 -08002173void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
2174 TimeSeries states("DTLS Transport State", LineStyle::kNone,
2175 PointStyle::kHighlight);
2176 for (const auto& event : parsed_log_.dtls_transport_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002177 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002178 float y = static_cast<float>(event.dtls_transport_state);
2179 states.points.emplace_back(x, y);
2180 }
2181 plot->AppendTimeSeries(std::move(states));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002182 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2183 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002184 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
2185 "Numeric Transport State", kBottomMargin, kTopMargin);
2186 plot->SetTitle("DTLS Transport State");
2187}
2188
2189void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2190 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2191 PointStyle::kHighlight);
2192 for (const auto& event : parsed_log_.dtls_writable_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002193 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002194 float y = static_cast<float>(event.writable);
2195 writable.points.emplace_back(x, y);
2196 }
2197 plot->AppendTimeSeries(std::move(writable));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002198 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2199 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002200 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2201 plot->SetTitle("DTLS Writable State");
2202}
2203
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002204void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002205 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002206 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2207 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2208 }
2209 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2210 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2211 }
2212 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2213 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2214 }
2215 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2216 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2217 }
2218 for (const auto& alert : incoming_seq_num_jumps_) {
2219 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2220 }
2221 for (const auto& alert : incoming_capture_time_jumps_) {
2222 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2223 }
2224 for (const auto& alert : outgoing_seq_num_jumps_) {
2225 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2226 }
2227 for (const auto& alert : outgoing_capture_time_jumps_) {
2228 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2229 }
2230 for (const auto& alert : outgoing_high_loss_alerts_) {
2231 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002232 }
2233 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2234}
2235
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002236void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2237 // With 100 packets/s (~800kbps), false positives would require 10 s without
2238 // data.
2239 constexpr int64_t kMaxSeqNumJump = 1000;
2240 // With a 90 kHz clock, false positives would require 10 s without data.
2241 constexpr int64_t kMaxCaptureTimeJump = 900000;
2242
2243 int64_t end_time_us = log_segments_.empty()
2244 ? std::numeric_limits<int64_t>::max()
2245 : log_segments_.front().second;
2246
2247 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002248 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002249 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002250 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002251 // Check for gaps in sequence numbers and capture timestamps.
2252 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2253 for (const auto& packet : stream.packet_view) {
2254 if (packet.log_time_us() > end_time_us) {
2255 // Only process the first (LOG_START, LOG_END) segment.
2256 break;
2257 }
2258
2259 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2260 if (last_seq_num.has_value() &&
2261 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002262 Alert_SeqNumJump(direction,
2263 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002264 packet.header.ssrc);
2265 }
2266 last_seq_num.emplace(seq_num);
2267
2268 int64_t capture_time =
2269 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2270 if (last_capture_time.has_value() &&
2271 std::abs(capture_time - last_capture_time.value()) >
2272 kMaxCaptureTimeJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002273 Alert_CaptureTimeJump(direction,
2274 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002275 packet.header.ssrc);
2276 }
2277 last_capture_time.emplace(capture_time);
2278 }
2279 }
2280}
2281
2282void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2283 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2284 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2285 int64_t end_time_us = log_segments_.empty()
2286 ? std::numeric_limits<int64_t>::max()
2287 : log_segments_.front().second;
2288
2289 // TODO(terelius): The parser could provide a list of all packets, ordered
2290 // by time, for each direction.
2291 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2292 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2293 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2294 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2295 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002296 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002297 for (const auto& kv : rtp_in_direction) {
2298 int64_t timestamp = kv.first;
2299 if (timestamp > end_time_us) {
2300 // Only process the first (LOG_START, LOG_END) segment.
2301 break;
2302 }
2303 int64_t duration = timestamp - last_rtp_time.value_or(0);
2304 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2305 // No packet sent/received for more than 500 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002306 Alert_RtpLogTimeGap(direction, config_.GetCallTimeSec(timestamp),
2307 duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002308 }
2309 last_rtp_time.emplace(timestamp);
2310 }
2311
Danil Chapovalov431abd92018-06-18 12:54:17 +02002312 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002313 if (direction == kIncomingPacket) {
2314 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2315 if (rtcp.log_time_us() > end_time_us) {
2316 // Only process the first (LOG_START, LOG_END) segment.
2317 break;
2318 }
2319 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2320 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2321 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002322 Alert_RtcpLogTimeGap(direction,
2323 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002324 duration / 1000);
2325 }
2326 last_rtcp_time.emplace(rtcp.log_time_us());
2327 }
2328 } else {
2329 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2330 if (rtcp.log_time_us() > end_time_us) {
2331 // Only process the first (LOG_START, LOG_END) segment.
2332 break;
2333 }
2334 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2335 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2336 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002337 Alert_RtcpLogTimeGap(direction,
2338 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002339 duration / 1000);
2340 }
2341 last_rtcp_time.emplace(rtcp.log_time_us());
2342 }
2343 }
2344}
2345
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002346// TODO(terelius): Notifications could possibly be generated by the same code
2347// that produces the graphs. There is some code duplication that could be
2348// avoided, but that might be solved anyway when we move functionality from the
2349// analyzer to the parser.
2350void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002351 CreateStreamGapAlerts(kIncomingPacket);
2352 CreateStreamGapAlerts(kOutgoingPacket);
2353 CreateTransmissionGapAlerts(kIncomingPacket);
2354 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002355
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002356 int64_t end_time_us = log_segments_.empty()
2357 ? std::numeric_limits<int64_t>::max()
2358 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002359
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002360 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002361 // Loss feedback
2362 int64_t total_lost_packets = 0;
2363 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002364 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2365 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002366 // Only process the first (LOG_START, LOG_END) segment.
2367 break;
2368 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002369 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002370 bwe_update.expected_packets;
2371 total_lost_packets += lost_packets;
2372 total_expected_packets += bwe_update.expected_packets;
2373 }
2374 double avg_outgoing_loss =
2375 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002376 if (avg_outgoing_loss > kMaxLossFraction) {
2377 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002378 }
2379}
2380
terelius54ce6802016-07-13 06:44:41 -07002381} // namespace webrtc