blob: eaf28bf6ba31c035403062fdc80a188403e1cecf [file] [log] [blame]
terelius54ce6802016-07-13 06:44:41 -07001/*
2 * Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
Mirko Bonadei575998c2019-07-25 13:57:41 +020011#include "rtc_tools/rtc_event_log_visualizer/analyzer.h"
terelius54ce6802016-07-13 06:44:41 -070012
13#include <algorithm>
Oleh Prypin6581f212017-11-16 00:17:05 +010014#include <cmath>
terelius54ce6802016-07-13 06:44:41 -070015#include <limits>
16#include <map>
Mirko Bonadei317a1f02019-09-17 17:06:18 +020017#include <memory>
terelius54ce6802016-07-13 06:44:41 -070018#include <string>
19#include <utility>
20
Björn Tereliusc69c1bb2019-10-11 15:06:58 +020021#include "absl/algorithm/container.h"
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +010022#include "absl/strings/string_view.h"
Artem Titov741daaf2019-03-21 14:37:36 +010023#include "api/function_view.h"
Sebastian Jansson95edb032019-01-17 16:24:12 +010024#include "api/transport/field_trial_based_config.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020025#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020026#include "call/audio_receive_stream.h"
27#include "call/audio_send_stream.h"
28#include "call/call.h"
29#include "call/video_receive_stream.h"
30#include "call/video_send_stream.h"
Elad Alon99a81b62017-09-21 10:25:29 +020031#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020032#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020033#include "modules/audio_coding/neteq/tools/audio_sink.h"
34#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
35#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
36#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
37#include "modules/audio_coding/neteq/tools/neteq_test.h"
38#include "modules/audio_coding/neteq/tools/resample_input_audio_file.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020039#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
40#include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020041#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020042#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020043#include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
Erik Språnge7942432019-06-12 13:30:02 +020044#include "modules/pacing/paced_sender.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010045#include "modules/pacing/packet_router.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020046#include "modules/remote_bitrate_estimator/include/bwe_defines.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020047#include "modules/rtp_rtcp/include/rtp_rtcp.h"
48#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020049#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020050#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
51#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
52#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
53#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
54#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
55#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
56#include "modules/rtp_rtcp/source/rtp_utility.h"
57#include "rtc_base/checks.h"
58#include "rtc_base/format_macros.h"
59#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020060#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020061#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020062#include "rtc_base/strings/string_builder.h"
Mirko Bonadei575998c2019-07-25 13:57:41 +020063#include "rtc_tools/rtc_event_log_visualizer/log_simulation.h"
terelius54ce6802016-07-13 06:44:41 -070064
Bjorn Terelius6984ad22017-10-24 12:19:45 +020065#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
66#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
67#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
68
tereliusdc35dcd2016-08-01 12:03:27 -070069namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070070
terelius54ce6802016-07-13 06:44:41 -070071namespace {
72
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080073const int kNumMicrosecsPerSec = 1000000;
74
terelius54ce6802016-07-13 06:44:41 -070075std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020076 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070077 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020078 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070079}
80
81// Checks whether an SSRC is contained in the list of desired SSRCs.
82// Note that an empty SSRC list matches every SSRC.
83bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
Mirko Bonadei1f173152019-07-25 15:28:14 +020084 if (desired_ssrc.empty())
terelius54ce6802016-07-13 06:44:41 -070085 return true;
86 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
87 desired_ssrc.end();
88}
89
90double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
91 // The timestamp is a fixed point representation with 6 bits for seconds
92 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080093 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
94 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070095 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080096 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -070097 return abs_send_time * kTimestampToMicroSec;
98}
99
100// Computes the difference |later| - |earlier| where |later| and |earlier|
101// are counters that wrap at |modulus|. The difference is chosen to have the
102// least absolute value. For example if |modulus| is 8, then the difference will
103// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
104// be in [-4, 4].
105int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
106 RTC_DCHECK_LE(1, modulus);
107 RTC_DCHECK_LT(later, modulus);
108 RTC_DCHECK_LT(earlier, modulus);
109 int64_t difference =
110 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
111 int64_t max_difference = modulus / 2;
112 int64_t min_difference = max_difference - modulus + 1;
113 if (difference > max_difference) {
114 difference -= modulus;
115 }
116 if (difference < min_difference) {
117 difference += modulus;
118 }
terelius6addf492016-08-23 17:34:07 -0700119 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100120 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
121 << " expected to be in the range ("
122 << min_difference / 2 << "," << max_difference / 2
123 << ") but is " << difference
124 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700125 }
terelius54ce6802016-07-13 06:44:41 -0700126 return difference;
127}
128
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200129// This is much more reliable for outgoing streams than for incoming streams.
130template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200131absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200132 const RtpPacketContainer& packets,
133 int64_t end_time_us) {
134 RTC_CHECK(packets.size() >= 2);
135 SeqNumUnwrapper<uint32_t> unwrapper;
Philip Eliasson1f850a62019-03-19 12:15:00 +0000136 int64_t first_rtp_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200137 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
138 int64_t first_log_timestamp = packets[0].log_time_us();
Philip Eliasson1f850a62019-03-19 12:15:00 +0000139 int64_t last_rtp_timestamp = first_rtp_timestamp;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200140 int64_t last_log_timestamp = first_log_timestamp;
141 for (size_t i = 1; i < packets.size(); i++) {
142 if (packets[i].log_time_us() > end_time_us)
143 break;
144 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
145 last_log_timestamp = packets[i].log_time_us();
146 }
147 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
148 RTC_LOG(LS_WARNING)
149 << "Failed to estimate RTP clock frequency: Stream too short. ("
150 << packets.size() << " packets, "
151 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200152 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200153 }
154 double duration =
155 static_cast<double>(last_log_timestamp - first_log_timestamp) /
156 kNumMicrosecsPerSec;
157 double estimated_frequency =
158 (last_rtp_timestamp - first_rtp_timestamp) / duration;
159 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
philipel3fa49382019-08-20 15:59:57 +0200160 if (std::fabs(estimated_frequency - f) < 0.15 * f) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200161 return f;
162 }
163 }
164 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
165 << estimated_frequency
philipel3fa49382019-08-20 15:59:57 +0200166 << " not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200167 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700168}
169
tereliusdc35dcd2016-08-01 12:03:27 -0700170constexpr float kLeftMargin = 0.01f;
171constexpr float kRightMargin = 0.02f;
172constexpr float kBottomMargin = 0.02f;
173constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700174
Danil Chapovalov431abd92018-06-18 12:54:17 +0200175absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100176 const LoggedRtpPacketIncoming& old_packet,
177 const LoggedRtpPacketIncoming& new_packet) {
178 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
179 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700180 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100181 new_packet.rtp.header.extension.absoluteSendTime,
182 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200183 int64_t recv_time_diff =
184 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700185 double delay_change_us =
186 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100187 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700188 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200189 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700190 }
191}
192
Danil Chapovalov431abd92018-06-18 12:54:17 +0200193absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100194 const LoggedRtpPacketIncoming& old_packet,
195 const LoggedRtpPacketIncoming& new_packet,
196 const double sample_rate) {
197 int64_t send_time_diff =
198 WrappingDifference(new_packet.rtp.header.timestamp,
199 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200200 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700201
terelius53dc23c2017-03-13 05:24:05 -0700202 double delay_change =
203 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100204 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700205 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100206 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100207 RTC_LOG(LS_WARNING) << "Old capture time "
208 << old_packet.rtp.header.timestamp << ", received time "
209 << old_packet.log_time_us();
210 RTC_LOG(LS_WARNING) << "New capture time "
211 << new_packet.rtp.header.timestamp << ", received time "
212 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100213 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800214 << static_cast<double>(recv_time_diff) /
215 kNumMicrosecsPerSec
216 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100217 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100218 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100219 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700220 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100221 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700222}
223
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200224// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700225// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200226template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200227void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200228 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200229 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200230 TimeSeries* result) {
231 for (size_t i = 0; i < data_view.size(); i++) {
232 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200233 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200234 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700235 if (y)
236 result->points.emplace_back(x, *y);
237 }
238}
239
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200240// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700241// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
242// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200243template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700244void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200245 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200246 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
247 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200248 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700249 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700250 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200251 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200252 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700253 if (y)
254 result->points.emplace_back(x, static_cast<float>(*y));
255 }
256}
257
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200258// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700259// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
260// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200261template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700262void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200263 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200264 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
265 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200266 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700267 TimeSeries* result) {
268 ResultType sum = 0;
269 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200270 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200271 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100272 if (y) {
terelius53dc23c2017-03-13 05:24:05 -0700273 sum += *y;
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100274 result->points.emplace_back(x, static_cast<float>(sum));
275 }
tereliusccbbf8d2016-08-10 07:34:28 -0700276 }
277}
278
terelius6addf492016-08-23 17:34:07 -0700279// Calculates a moving average of |data| and stores the result in a TimeSeries.
280// A data point is generated every |step| microseconds from |begin_time|
281// to |end_time|. The value of each data point is the average of the data
Mirko Bonadei604e75c2019-07-25 11:55:47 +0200282// during the preceding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200283template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700284void MovingAverage(
Danil Chapovalov431abd92018-06-18 12:54:17 +0200285 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200286 const IterableType& data_view,
Bjorn Terelius068fc352019-02-13 22:38:25 +0100287 AnalyzerConfig config,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200288 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700289 size_t window_index_begin = 0;
290 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700291 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700292
Bjorn Terelius068fc352019-02-13 22:38:25 +0100293 for (int64_t t = config.begin_time_; t < config.end_time_ + config.step_;
294 t += config.step_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200295 while (window_index_end < data_view.size() &&
296 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200297 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700298 if (value)
299 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700300 ++window_index_end;
301 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200302 while (window_index_begin < data_view.size() &&
303 data_view[window_index_begin].log_time_us() <
Bjorn Terelius068fc352019-02-13 22:38:25 +0100304 t - config.window_duration_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200305 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700306 if (value)
307 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700308 ++window_index_begin;
309 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800310 float window_duration_s =
Bjorn Terelius068fc352019-02-13 22:38:25 +0100311 static_cast<float>(config.window_duration_) / kNumMicrosecsPerSec;
312 float x = config.GetCallTimeSec(t);
terelius53dc23c2017-03-13 05:24:05 -0700313 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700314 result->points.emplace_back(x, y);
315 }
316}
317
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100318template <typename T>
319TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
320 AnalyzerConfig config,
321 std::string rtcp_name,
322 int category_id) {
323 TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
324 for (const auto& rtcp : rtcp_list) {
325 float x = config.GetCallTimeSec(rtcp.log_time_us());
326 float y = category_id;
327 time_series.points.emplace_back(x, y);
328 }
329 return time_series;
330}
331
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800332const char kUnknownEnumValue[] = "unknown";
333
334const char kIceCandidateTypeLocal[] = "local";
335const char kIceCandidateTypeStun[] = "stun";
336const char kIceCandidateTypePrflx[] = "prflx";
337const char kIceCandidateTypeRelay[] = "relay";
338
339const char kProtocolUdp[] = "udp";
340const char kProtocolTcp[] = "tcp";
341const char kProtocolSsltcp[] = "ssltcp";
342const char kProtocolTls[] = "tls";
343
344const char kAddressFamilyIpv4[] = "ipv4";
345const char kAddressFamilyIpv6[] = "ipv6";
346
347const char kNetworkTypeEthernet[] = "ethernet";
348const char kNetworkTypeLoopback[] = "loopback";
349const char kNetworkTypeWifi[] = "wifi";
350const char kNetworkTypeVpn[] = "vpn";
351const char kNetworkTypeCellular[] = "cellular";
352
353std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
354 switch (type) {
355 case webrtc::IceCandidateType::kLocal:
356 return kIceCandidateTypeLocal;
357 case webrtc::IceCandidateType::kStun:
358 return kIceCandidateTypeStun;
359 case webrtc::IceCandidateType::kPrflx:
360 return kIceCandidateTypePrflx;
361 case webrtc::IceCandidateType::kRelay:
362 return kIceCandidateTypeRelay;
363 default:
364 return kUnknownEnumValue;
365 }
366}
367
368std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
369 switch (protocol) {
370 case webrtc::IceCandidatePairProtocol::kUdp:
371 return kProtocolUdp;
372 case webrtc::IceCandidatePairProtocol::kTcp:
373 return kProtocolTcp;
374 case webrtc::IceCandidatePairProtocol::kSsltcp:
375 return kProtocolSsltcp;
376 case webrtc::IceCandidatePairProtocol::kTls:
377 return kProtocolTls;
378 default:
379 return kUnknownEnumValue;
380 }
381}
382
383std::string GetAddressFamilyAsString(
384 webrtc::IceCandidatePairAddressFamily family) {
385 switch (family) {
386 case webrtc::IceCandidatePairAddressFamily::kIpv4:
387 return kAddressFamilyIpv4;
388 case webrtc::IceCandidatePairAddressFamily::kIpv6:
389 return kAddressFamilyIpv6;
390 default:
391 return kUnknownEnumValue;
392 }
393}
394
395std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
396 switch (type) {
397 case webrtc::IceCandidateNetworkType::kEthernet:
398 return kNetworkTypeEthernet;
399 case webrtc::IceCandidateNetworkType::kLoopback:
400 return kNetworkTypeLoopback;
401 case webrtc::IceCandidateNetworkType::kWifi:
402 return kNetworkTypeWifi;
403 case webrtc::IceCandidateNetworkType::kVpn:
404 return kNetworkTypeVpn;
405 case webrtc::IceCandidateNetworkType::kCellular:
406 return kNetworkTypeCellular;
407 default:
408 return kUnknownEnumValue;
409 }
410}
411
412std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200413 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800414 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
415 // represents a pair of a local server-reflexive candidate on a WiFi network
416 // and a remote relay candidate using TCP as the relay protocol on a cell
417 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200418 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800419 std::string local_candidate_type =
420 GetIceCandidateTypeAsString(config.local_candidate_type);
421 std::string remote_candidate_type =
422 GetIceCandidateTypeAsString(config.remote_candidate_type);
423 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
424 local_candidate_type +=
425 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
426 }
427 ss << local_candidate_type << ":"
428 << GetNetworkTypeAsString(config.local_network_type) << ":"
429 << GetAddressFamilyAsString(config.local_address_family) << "->"
430 << remote_candidate_type << ":"
431 << GetAddressFamilyAsString(config.remote_address_family) << "@"
432 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200433 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800434}
435
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200436std::string GetDirectionAsString(PacketDirection direction) {
437 if (direction == kIncomingPacket) {
438 return "Incoming";
439 } else {
440 return "Outgoing";
441 }
442}
443
444std::string GetDirectionAsShortString(PacketDirection direction) {
445 if (direction == kIncomingPacket) {
446 return "In";
447 } else {
448 return "Out";
449 }
450}
451
terelius54ce6802016-07-13 06:44:41 -0700452} // namespace
453
Sebastian Janssonb290a6d2019-01-03 14:46:23 +0100454EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200455 bool normalize_time)
Bjorn Terelius068fc352019-02-13 22:38:25 +0100456 : parsed_log_(log) {
457 config_.window_duration_ = 250000;
458 config_.step_ = 10000;
459 config_.normalize_time_ = normalize_time;
460 config_.begin_time_ = parsed_log_.first_timestamp();
461 config_.end_time_ = parsed_log_.last_timestamp();
462 if (config_.end_time_ < config_.begin_time_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200463 RTC_LOG(LS_WARNING) << "No useful events in the log.";
Bjorn Terelius068fc352019-02-13 22:38:25 +0100464 config_.begin_time_ = config_.end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000465 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200466
467 const auto& log_start_events = parsed_log_.start_log_events();
468 const auto& log_end_events = parsed_log_.stop_log_events();
469 auto start_iter = log_start_events.begin();
470 auto end_iter = log_end_events.begin();
471 while (start_iter != log_start_events.end()) {
472 int64_t start = start_iter->log_time_us();
473 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200474 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200475 if (start_iter != log_start_events.end())
476 next_start.emplace(start_iter->log_time_us());
477 if (end_iter != log_end_events.end() &&
478 end_iter->log_time_us() <=
479 next_start.value_or(std::numeric_limits<int64_t>::max())) {
480 int64_t end = end_iter->log_time_us();
481 RTC_DCHECK_LE(start, end);
482 log_segments_.push_back(std::make_pair(start, end));
483 ++end_iter;
484 } else {
485 // we're missing an end event. Assume that it occurred just before the
486 // next start.
487 log_segments_.push_back(
Bjorn Terelius068fc352019-02-13 22:38:25 +0100488 std::make_pair(start, next_start.value_or(config_.end_time_)));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200489 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700490 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100491 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200492 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700493}
494
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200495class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200496 public:
497 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
498
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200499 void Update(NetworkControlUpdate update) {
500 if (update.target_rate) {
501 last_bitrate_bps_ = update.target_rate->target_rate.bps();
502 bitrate_updated_ = true;
503 }
Stefan Holmer13181032016-07-29 14:48:54 +0200504 }
505
506 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
507 uint32_t bitrate) override {}
508
509 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
510 bool GetAndResetBitrateUpdated() {
511 bool bitrate_updated = bitrate_updated_;
512 bitrate_updated_ = false;
513 return bitrate_updated;
514 }
515
516 private:
517 uint32_t last_bitrate_bps_;
518 bool bitrate_updated_;
519};
520
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200521void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700522 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200523 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
524 // Filter on SSRC.
525 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700526 continue;
terelius54ce6802016-07-13 06:44:41 -0700527 }
terelius54ce6802016-07-13 06:44:41 -0700528
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200529 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
530 LineStyle::kBar);
531 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200532 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200533 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200534 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100535 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200536 };
537 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
538 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700539 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700540 }
541
Bjorn Terelius068fc352019-02-13 22:38:25 +0100542 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
543 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700544 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
545 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200546 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700547}
548
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100549void EventLogAnalyzer::CreateRtcpTypeGraph(PacketDirection direction,
550 Plot* plot) {
551 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
552 parsed_log_.transport_feedbacks(direction), config_, "TWCC", 1));
553 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
554 parsed_log_.receiver_reports(direction), config_, "RR", 2));
555 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
556 parsed_log_.sender_reports(direction), config_, "SR", 3));
557 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
558 parsed_log_.extended_reports(direction), config_, "XR", 4));
559 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.nacks(direction),
560 config_, "NACK", 5));
561 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.rembs(direction),
562 config_, "REMB", 6));
563 plot->AppendTimeSeries(
564 CreateRtcpTypeTimeSeries(parsed_log_.firs(direction), config_, "FIR", 7));
565 plot->AppendTimeSeries(
566 CreateRtcpTypeTimeSeries(parsed_log_.plis(direction), config_, "PLI", 8));
567 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
568 "Time (s)", kLeftMargin, kRightMargin);
569 plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
570 plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
Bjorn Tereliusf640b872019-07-24 15:46:39 +0200571 plot->SetYAxisTickLabels({{1, "TWCC"},
572 {2, "RR"},
573 {3, "SR"},
574 {4, "XR"},
575 {5, "NACK"},
576 {6, "REMB"},
577 {7, "FIR"},
578 {8, "PLI"}});
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100579}
580
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200581template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700582void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700583 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200584 const IterableType& packets,
585 const std::string& label) {
586 TimeSeries time_series(label, LineStyle::kStep);
587 for (size_t i = 0; i < packets.size(); i++) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100588 float x = config_.GetCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200589 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700590 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200591 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700592}
593
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200594void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
595 Plot* plot) {
596 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
597 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
598 continue;
599 std::string label =
600 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
601 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
602 }
603 std::string label =
604 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
605 if (direction == kIncomingPacket) {
606 CreateAccumulatedPacketsTimeSeries(
607 plot, parsed_log_.incoming_rtcp_packets(), label);
608 } else {
609 CreateAccumulatedPacketsTimeSeries(
610 plot, parsed_log_.outgoing_rtcp_packets(), label);
611 }
philipelccd74892016-09-05 02:46:25 -0700612
Bjorn Terelius068fc352019-02-13 22:38:25 +0100613 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
614 "Time (s)", kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700615 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200616 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
617 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700618}
619
Kristoffer Erlandsson283c1062020-03-30 13:01:37 +0200620void EventLogAnalyzer::CreatePacketRateGraph(PacketDirection direction,
621 Plot* plot) {
622 auto CountPackets = [](auto packet) { return 1.0; };
623 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
624 // Filter on SSRC.
625 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
626 continue;
627 }
628 TimeSeries time_series(
629 std::string("RTP ") + GetStreamName(direction, stream.ssrc),
630 LineStyle::kLine);
631 MovingAverage<LoggedRtpPacket, double>(CountPackets, stream.packet_view,
632 config_, &time_series);
633 plot->AppendTimeSeries(std::move(time_series));
634 }
635 TimeSeries time_series(
636 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")",
637 LineStyle::kLine);
638 if (direction == kIncomingPacket) {
639 MovingAverage<LoggedRtcpPacketIncoming, double>(
640 CountPackets, parsed_log_.incoming_rtcp_packets(), config_,
641 &time_series);
642 } else {
643 MovingAverage<LoggedRtcpPacketOutgoing, double>(
644 CountPackets, parsed_log_.outgoing_rtcp_packets(), config_,
645 &time_series);
646 }
647 plot->AppendTimeSeries(std::move(time_series));
648
649 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
650 "Time (s)", kLeftMargin, kRightMargin);
651 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
652 kTopMargin);
653 plot->SetTitle("Rate of " + GetDirectionAsString(direction) +
654 " RTP/RTCP packets");
655}
656
terelius54ce6802016-07-13 06:44:41 -0700657// For each SSRC, plot the time between the consecutive playouts.
658void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200659 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
660 uint32_t ssrc = playout_stream.first;
661 if (!MatchingSsrc(ssrc, desired_ssrc_))
662 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200663 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200664 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200665 for (const auto& playout_event : playout_stream.second) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100666 float x = config_.GetCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200667 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200668 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200669 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200670 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200671 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700672 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200673 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700674 }
675
Bjorn Terelius068fc352019-02-13 22:38:25 +0100676 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
677 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700678 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
679 kTopMargin);
680 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700681}
682
ivocaac9d6f2016-09-22 07:01:47 -0700683// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200684void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
685 Plot* plot) {
686 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
687 if (!IsAudioSsrc(direction, stream.ssrc))
688 continue;
689 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
690 LineStyle::kLine);
691 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700692 if (packet.header.extension.hasAudioLevel) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100693 float x = config_.GetCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700694 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
695 // Here we convert it to dBov.
696 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200697 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700698 }
699 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200700 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700701 }
702
Bjorn Terelius068fc352019-02-13 22:38:25 +0100703 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
704 "Time (s)", kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200705 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200706 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700707}
708
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100709// For each SSRC, plot the sequence number difference between consecutive
710// incoming packets.
terelius54ce6802016-07-13 06:44:41 -0700711void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200712 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
713 // Filter on SSRC.
714 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700715 continue;
terelius54ce6802016-07-13 06:44:41 -0700716 }
terelius54ce6802016-07-13 06:44:41 -0700717
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200718 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
719 LineStyle::kBar);
720 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
721 const LoggedRtpPacketIncoming& new_packet) {
722 int64_t diff =
723 WrappingDifference(new_packet.rtp.header.sequenceNumber,
724 old_packet.rtp.header.sequenceNumber, 1ul << 16);
725 return diff;
726 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200727 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100728 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200729 };
730 ProcessPairs<LoggedRtpPacketIncoming, float>(
731 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
732 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700733 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700734 }
735
Bjorn Terelius068fc352019-02-13 22:38:25 +0100736 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
737 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700738 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
739 kTopMargin);
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100740 plot->SetTitle("Incoming sequence number delta");
terelius54ce6802016-07-13 06:44:41 -0700741}
742
Stefan Holmer99f8e082016-09-09 13:37:50 +0200743void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200744 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
745 const std::vector<LoggedRtpPacketIncoming>& packets =
746 stream.incoming_packets;
747 // Filter on SSRC.
Mirko Bonadei1f173152019-07-25 15:28:14 +0200748 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.empty()) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200749 continue;
750 }
751
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200752 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
753 LineStyle::kLine, PointStyle::kHighlight);
754 // TODO(terelius): Should the window and step size be read from the class
755 // instead?
756 const int64_t kWindowUs = 1000000;
757 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100758 SeqNumUnwrapper<uint16_t> unwrapper_;
759 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800760 size_t window_index_begin = 0;
761 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200762 uint64_t highest_seq_number =
763 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
764 uint64_t highest_prior_seq_number =
765 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800766
Bjorn Terelius068fc352019-02-13 22:38:25 +0100767 for (int64_t t = config_.begin_time_; t < config_.end_time_ + kStep;
768 t += kStep) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200769 while (window_index_end < packets.size() &&
770 packets[window_index_end].rtp.log_time_us() < t) {
771 uint64_t sequence_number = unwrapper_.Unwrap(
772 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800773 highest_seq_number = std::max(highest_seq_number, sequence_number);
774 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200775 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200776 while (window_index_begin < packets.size() &&
777 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
778 uint64_t sequence_number = prior_unwrapper_.Unwrap(
779 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800780 highest_prior_seq_number =
781 std::max(highest_prior_seq_number, sequence_number);
782 ++window_index_begin;
783 }
Bjorn Terelius068fc352019-02-13 22:38:25 +0100784 float x = config_.GetCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200785 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800786 if (expected_packets > 0) {
787 int64_t received_packets = window_index_end - window_index_begin;
788 int64_t lost_packets = expected_packets - received_packets;
789 float y = static_cast<float>(lost_packets) / expected_packets * 100;
790 time_series.points.emplace_back(x, y);
791 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200792 }
philipel35ba9bd2017-04-19 05:58:51 -0700793 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200794 }
795
Bjorn Terelius068fc352019-02-13 22:38:25 +0100796 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
797 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100798 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
799 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
Stefan Holmer99f8e082016-09-09 13:37:50 +0200800}
801
terelius2ee076d2017-08-15 02:04:02 -0700802void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100803 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200804 // Filter on SSRC.
805 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200806 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700807 continue;
808 }
terelius54ce6802016-07-13 06:44:41 -0700809
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100810 const std::vector<LoggedRtpPacketIncoming>& packets =
811 stream.incoming_packets;
812 if (packets.size() < 100) {
813 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
814 << packets.size() << " packets in the stream.";
815 continue;
816 }
817 int64_t end_time_us = log_segments_.empty()
818 ? std::numeric_limits<int64_t>::max()
819 : log_segments_.front().second;
820 absl::optional<uint32_t> estimated_frequency =
821 EstimateRtpClockFrequency(packets, end_time_us);
822 if (!estimated_frequency)
823 continue;
824 const double frequency_hz = *estimated_frequency;
825 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
826 RTC_LOG(LS_WARNING)
827 << "Video stream should use a 90 kHz clock but appears to use "
828 << frequency_hz / 1000 << ". Discarding.";
829 continue;
830 }
831
832 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100833 return this->config_.GetCallTimeSec(packet.log_time_us());
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100834 };
835 auto ToNetworkDelay = [frequency_hz](
836 const LoggedRtpPacketIncoming& old_packet,
837 const LoggedRtpPacketIncoming& new_packet) {
838 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
839 };
840
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200841 TimeSeries capture_time_data(
842 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
843 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100844 AccumulatePairs<LoggedRtpPacketIncoming, double>(
845 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700846 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700847
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200848 TimeSeries send_time_data(
849 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
850 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100851 AccumulatePairs<LoggedRtpPacketIncoming, double>(
852 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
853 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700854 }
855
Bjorn Terelius068fc352019-02-13 22:38:25 +0100856 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
857 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +0100858 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
859 plot->SetTitle("Incoming network delay (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700860}
861
tereliusf736d232016-08-04 10:00:11 -0700862// Plot the fraction of packets lost (as perceived by the loss-based BWE).
863void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100864 TimeSeries time_series("Fraction lost", LineStyle::kLine,
865 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200866 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100867 float x = config_.GetCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200868 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700869 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700870 }
tereliusf736d232016-08-04 10:00:11 -0700871
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200872 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +0100873 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
874 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100875 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
876 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
tereliusf736d232016-08-04 10:00:11 -0700877}
878
terelius54ce6802016-07-13 06:44:41 -0700879// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200880void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
881 // TODO(terelius): This could be provided by the parser.
882 std::multimap<int64_t, size_t> packets_in_order;
883 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
884 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
885 packets_in_order.insert(
886 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700887 }
888
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200889 auto window_begin = packets_in_order.begin();
890 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700891 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700892
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800893 if (!packets_in_order.empty()) {
894 // Calculate a moving average of the bitrate and store in a TimeSeries.
895 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
896 for (int64_t time = config_.begin_time_;
897 time < config_.end_time_ + config_.step_; time += config_.step_) {
898 while (window_end != packets_in_order.end() && window_end->first < time) {
899 bytes_in_window += window_end->second;
900 ++window_end;
901 }
902 while (window_begin != packets_in_order.end() &&
903 window_begin->first < time - config_.window_duration_) {
904 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
905 bytes_in_window -= window_begin->second;
906 ++window_begin;
907 }
908 float window_duration_in_seconds =
909 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
910 float x = config_.GetCallTimeSec(time);
911 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
912 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700913 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800914 plot->AppendTimeSeries(std::move(bitrate_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200915 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200916
917 // Overlay the outgoing REMB over incoming bitrate.
918 TimeSeries remb_series("Remb", LineStyle::kStep);
919 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100920 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200921 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
922 remb_series.points.emplace_back(x, y);
923 }
924 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
925
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800926 if (!parsed_log_.generic_packets_received().empty()) {
927 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
928 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
929 return packet.packet_length * 8.0 / 1000.0;
930 };
931 MovingAverage<LoggedGenericPacketReceived, double>(
932 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
933 &time_series);
934 plot->AppendTimeSeries(std::move(time_series));
935 }
936
Bjorn Terelius068fc352019-02-13 22:38:25 +0100937 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
938 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200939 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
940 plot->SetTitle("Incoming RTP bitrate");
941}
942
943// Plot the total bandwidth used by all RTP streams.
944void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
945 bool show_detector_state,
946 bool show_alr_state) {
947 // TODO(terelius): This could be provided by the parser.
948 std::multimap<int64_t, size_t> packets_in_order;
949 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
950 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
951 packets_in_order.insert(
952 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
953 }
954
955 auto window_begin = packets_in_order.begin();
956 auto window_end = packets_in_order.begin();
957 size_t bytes_in_window = 0;
958
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800959 if (!packets_in_order.empty()) {
960 // Calculate a moving average of the bitrate and store in a TimeSeries.
961 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
962 for (int64_t time = config_.begin_time_;
963 time < config_.end_time_ + config_.step_; time += config_.step_) {
964 while (window_end != packets_in_order.end() && window_end->first < time) {
965 bytes_in_window += window_end->second;
966 ++window_end;
967 }
968 while (window_begin != packets_in_order.end() &&
969 window_begin->first < time - config_.window_duration_) {
970 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
971 bytes_in_window -= window_begin->second;
972 ++window_begin;
973 }
974 float window_duration_in_seconds =
975 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
976 float x = config_.GetCallTimeSec(time);
977 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
978 bitrate_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200979 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800980 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700981 }
982
terelius8058e582016-07-25 01:32:41 -0700983 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200984 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
985 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100986 float x = config_.GetCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200987 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
988 loss_series.points.emplace_back(x, y);
989 }
philipel10fc0e62017-04-11 01:50:23 -0700990
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200991 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
992 IntervalSeries overusing_series("Overusing", "#ff8e82",
993 IntervalSeries::kHorizontal);
994 IntervalSeries underusing_series("Underusing", "#5092fc",
995 IntervalSeries::kHorizontal);
996 IntervalSeries normal_series("Normal", "#c4ffc4",
997 IntervalSeries::kHorizontal);
998 IntervalSeries* last_series = &normal_series;
999 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -07001000
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001001 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -07001002
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001003 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001004 float x = config_.GetCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001005 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -07001006
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001007 if (last_detector_state != delay_update.detector_state) {
1008 last_series->intervals.emplace_back(last_detector_switch, x);
1009 last_detector_state = delay_update.detector_state;
1010 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -07001011
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001012 switch (delay_update.detector_state) {
1013 case BandwidthUsage::kBwNormal:
1014 last_series = &normal_series;
1015 break;
1016 case BandwidthUsage::kBwUnderusing:
1017 last_series = &underusing_series;
1018 break;
1019 case BandwidthUsage::kBwOverusing:
1020 last_series = &overusing_series;
1021 break;
1022 case BandwidthUsage::kLast:
1023 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +02001024 }
1025 }
philipel23c7f252017-07-14 06:30:03 -07001026
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001027 delay_series.points.emplace_back(x, y);
1028 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +02001029
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001030 RTC_CHECK(last_series);
Bjorn Terelius068fc352019-02-13 22:38:25 +01001031 last_series->intervals.emplace_back(last_detector_switch, config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001032
1033 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
1034 PointStyle::kHighlight);
1035 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001036 float x = config_.GetCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001037 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
1038 created_series.points.emplace_back(x, y);
1039 }
1040
1041 TimeSeries result_series("Probing results.", LineStyle::kNone,
1042 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001043 for (auto& result : parsed_log_.bwe_probe_success_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001044 float x = config_.GetCallTimeSec(result.log_time_us());
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001045 float y = static_cast<float>(result.bitrate_bps) / 1000;
1046 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001047 }
1048
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001049 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1050 PointStyle::kHighlight);
1051 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001052 float x = config_.GetCallTimeSec(failure.log_time_us());
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001053 probe_failures_series.points.emplace_back(x, 0);
1054 }
1055
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001056 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1057 bool previously_in_alr = false;
1058 int64_t alr_start = 0;
1059 for (auto& alr : parsed_log_.alr_state_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001060 float y = config_.GetCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001061 if (!previously_in_alr && alr.in_alr) {
1062 alr_start = alr.log_time_us();
1063 previously_in_alr = true;
1064 } else if (previously_in_alr && !alr.in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001065 float x = config_.GetCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +01001066 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001067 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +00001068 }
Björn Tereliusff612732018-04-25 14:23:01 +00001069 }
1070
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001071 if (previously_in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001072 float x = config_.GetCallTimeSec(alr_start);
1073 float y = config_.GetCallTimeSec(config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001074 alr_state.intervals.emplace_back(x, y);
1075 }
1076
1077 if (show_detector_state) {
1078 plot->AppendIntervalSeries(std::move(overusing_series));
1079 plot->AppendIntervalSeries(std::move(underusing_series));
1080 plot->AppendIntervalSeries(std::move(normal_series));
1081 }
1082
1083 if (show_alr_state) {
1084 plot->AppendIntervalSeries(std::move(alr_state));
1085 }
1086 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001087 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001088 plot->AppendTimeSeries(std::move(delay_series));
1089 plot->AppendTimeSeries(std::move(created_series));
1090 plot->AppendTimeSeries(std::move(result_series));
1091
1092 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001093 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001094 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001095 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001096 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001097 remb_series.points.emplace_back(x, y);
1098 }
1099 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1100
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001101 if (!parsed_log_.generic_packets_sent().empty()) {
1102 {
1103 TimeSeries time_series("Outgoing generic total bitrate",
1104 LineStyle::kLine);
1105 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1106 return packet.packet_length() * 8.0 / 1000.0;
1107 };
1108 MovingAverage<LoggedGenericPacketSent, double>(
1109 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1110 &time_series);
1111 plot->AppendTimeSeries(std::move(time_series));
1112 }
1113
1114 {
1115 TimeSeries time_series("Outgoing generic payload bitrate",
1116 LineStyle::kLine);
1117 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1118 return packet.payload_length * 8.0 / 1000.0;
1119 };
1120 MovingAverage<LoggedGenericPacketSent, double>(
1121 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1122 &time_series);
1123 plot->AppendTimeSeries(std::move(time_series));
1124 }
1125 }
1126
Bjorn Terelius068fc352019-02-13 22:38:25 +01001127 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1128 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001129 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001130 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001131}
1132
1133// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001134void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1135 Plot* plot) {
1136 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1137 // Filter on SSRC.
1138 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001139 continue;
terelius54ce6802016-07-13 06:44:41 -07001140 }
1141
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001142 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1143 LineStyle::kLine);
1144 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1145 return packet.total_length * 8.0 / 1000.0;
1146 };
terelius53dc23c2017-03-13 05:24:05 -07001147 MovingAverage<LoggedRtpPacket, double>(
Bjorn Terelius068fc352019-02-13 22:38:25 +01001148 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001149 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001150 }
1151
Bjorn Terelius068fc352019-02-13 22:38:25 +01001152 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1153 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001154 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001155 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001156}
1157
Bjorn Terelius9775a582019-02-15 17:29:58 +01001158// Plot the bitrate allocation for each temporal and spatial layer.
1159// Computed from RTCP XR target bitrate block, so the graph is only populated if
1160// those are sent.
1161void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1162 Plot* plot) {
1163 std::map<LayerDescription, TimeSeries> time_series;
1164 const auto& xr_list = parsed_log_.extended_reports(direction);
1165 for (const auto& rtcp : xr_list) {
1166 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1167 rtcp.xr.target_bitrate();
1168 if (!target_bitrate.has_value())
1169 continue;
1170 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1171 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1172 bitrate_item.temporal_layer);
1173 auto time_series_it = time_series.find(layer);
1174 if (time_series_it == time_series.end()) {
1175 std::string layer_name = GetLayerName(layer);
1176 bool inserted;
1177 std::tie(time_series_it, inserted) = time_series.insert(
1178 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1179 RTC_DCHECK(inserted);
1180 }
1181 float x = config_.GetCallTimeSec(rtcp.log_time_us());
1182 float y = bitrate_item.target_bitrate_kbps;
1183 time_series_it->second.points.emplace_back(x, y);
1184 }
1185 }
1186 for (auto& layer : time_series) {
1187 plot->AppendTimeSeries(std::move(layer.second));
1188 }
1189 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1190 "Time (s)", kLeftMargin, kRightMargin);
1191 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1192 if (direction == kIncomingPacket)
1193 plot->SetTitle("Target bitrate per incoming layer");
1194 else
1195 plot->SetTitle("Target bitrate per outgoing layer");
1196}
1197
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001198void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1199 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1200 PointStyle::kHighlight);
1201 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1202 PointStyle::kHighlight);
1203 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1204 PointStyle::kHighlight);
1205 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1206 PointStyle::kHighlight);
1207
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001208 LogBasedNetworkControllerSimulation simulation(
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001209 std::make_unique<GoogCcNetworkControllerFactory>(),
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001210 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1211 if (update.target_rate) {
1212 target_rates.points.emplace_back(
1213 config_.GetCallTimeSec(at_time.us()),
1214 update.target_rate->target_rate.kbps<float>());
1215 }
1216 });
1217
1218 simulation.ProcessEventsInLog(parsed_log_);
1219 for (const auto& logged : parsed_log_.bwe_delay_updates())
1220 delay_based.points.emplace_back(
1221 config_.GetCallTimeSec(logged.log_time_us()),
1222 logged.bitrate_bps / 1000);
1223 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1224 probe_results.points.emplace_back(
1225 config_.GetCallTimeSec(logged.log_time_us()),
1226 logged.bitrate_bps / 1000);
1227 for (const auto& logged : parsed_log_.bwe_loss_updates())
1228 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time_us()),
1229 logged.bitrate_bps / 1000);
1230
1231 plot->AppendTimeSeries(std::move(delay_based));
1232 plot->AppendTimeSeries(std::move(loss_based));
1233 plot->AppendTimeSeries(std::move(probe_results));
1234 plot->AppendTimeSeries(std::move(target_rates));
1235
1236 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1237 "Time (s)", kLeftMargin, kRightMargin);
1238 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1239 plot->SetTitle("Simulated BWE behavior");
1240}
1241
Bjorn Terelius28db2662017-10-04 14:22:43 +02001242void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001243 using RtpPacketType = LoggedRtpPacketOutgoing;
1244 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001245
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001246 // TODO(terelius): This could be provided by the parser.
1247 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1248 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1249 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1250 outgoing_rtp.insert(
1251 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001252 }
1253
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001254 const std::vector<TransportFeedbackType>& incoming_rtcp =
1255 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001256
1257 SimulatedClock clock(0);
1258 BitrateObserver observer;
Danil Chapovalov83bbe912019-08-07 12:24:53 +02001259 RtcEventLogNull null_event_log;
nisse0245da02016-11-30 03:35:20 -08001260 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001261 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001262 TransportFeedbackAdapter transport_feedback;
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001263 auto factory = GoogCcNetworkControllerFactory();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001264 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001265 // TODO(holmer): Log the call config and use that here instead.
1266 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001267 NetworkControllerConfig cc_config;
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001268 cc_config.constraints.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
Danil Chapovalovcad3e0e2020-02-17 18:46:07 +01001269 cc_config.constraints.starting_rate =
1270 DataRate::BitsPerSec(kDefaultStartBitrateBps);
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001271 cc_config.event_log = &null_event_log;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001272 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001273
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001274 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1275 PointStyle::kHighlight);
1276 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1277 PointStyle::kHighlight);
1278 TimeSeries acked_estimate_time_series(
1279 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001280
1281 auto rtp_iterator = outgoing_rtp.begin();
1282 auto rtcp_iterator = incoming_rtcp.begin();
1283
1284 auto NextRtpTime = [&]() {
1285 if (rtp_iterator != outgoing_rtp.end())
1286 return static_cast<int64_t>(rtp_iterator->first);
1287 return std::numeric_limits<int64_t>::max();
1288 };
1289
1290 auto NextRtcpTime = [&]() {
1291 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001292 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001293 return std::numeric_limits<int64_t>::max();
1294 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001295 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001296
1297 auto NextProcessTime = [&]() {
1298 if (rtcp_iterator != incoming_rtcp.end() ||
1299 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001300 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001301 }
1302 return std::numeric_limits<int64_t>::max();
1303 };
1304
Stefan Holmer492ee282016-10-27 17:19:20 +02001305 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001306#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001307 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001308 // The event_log_visualizer should normally not be compiled with
1309 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
Björn Terelius251b0dc2019-11-11 21:00:18 +01001310 // However, compiling with BWE_TEST_LOGGING, running with --plot=sendside_bwe
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001311 // and piping the output to plot_dynamics.py can be used as a hack to get the
1312 // internal state of various BWE components. In this case, it is important
1313 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
Sebastian Jansson4ad51d82019-06-11 11:24:40 +02001314 // GoogCcNetworkController since that would lead to duplicate outputs.
Björn Terelius251b0dc2019-11-11 21:00:18 +01001315 std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1316 acknowledged_bitrate_estimator(
1317 AcknowledgedBitrateEstimatorInterface::Create(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001318#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001319 int64_t time_us =
1320 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001321 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001322 while (time_us != std::numeric_limits<int64_t>::max()) {
1323 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001324 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1325 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1326 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1327 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1328 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
Erik Språng30a276b2019-04-23 12:00:11 +02001329 RtpPacketSendInfo packet_info;
1330 packet_info.ssrc = rtp_packet.rtp.header.ssrc;
Bjorn Tereliusf2e9cab2019-05-27 16:44:09 +02001331 packet_info.transport_sequence_number =
Erik Språng30a276b2019-04-23 12:00:11 +02001332 rtp_packet.rtp.header.extension.transportSequenceNumber;
1333 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
Erik Språng30a276b2019-04-23 12:00:11 +02001334 packet_info.length = rtp_packet.rtp.total_length;
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001335 transport_feedback.AddPacket(
Erik Språng30a276b2019-04-23 12:00:11 +02001336 packet_info,
1337 0u, // Per packet overhead bytes.
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001338 Timestamp::Micros(rtp_packet.rtp.log_time_us()));
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001339 rtc::SentPacket sent_packet(
1340 rtp_packet.rtp.header.extension.transportSequenceNumber,
1341 rtp_packet.rtp.log_time_us() / 1000);
1342 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1343 if (sent_msg)
1344 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1345 }
1346 ++rtp_iterator;
1347 }
Stefan Holmer13181032016-07-29 14:48:54 +02001348 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001349 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001350
1351 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001352 rtcp_iterator->transport_feedback,
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001353 Timestamp::Millis(clock.TimeInMilliseconds()));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001354 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001355 if (feedback_msg) {
1356 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001357 std::vector<PacketResult> feedback =
1358 feedback_msg->SortedByReceiveTime();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001359 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001360#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Björn Terelius251b0dc2019-11-11 21:00:18 +01001361 acknowledged_bitrate_estimator->IncomingPacketFeedbackVector(
1362 feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001363#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001364 for (const PacketResult& packet : feedback)
1365 acked_bitrate.Update(packet.sent_packet.size.bytes(),
1366 packet.receive_time.ms());
1367 bitrate_bps = acked_bitrate.Rate(feedback.back().receive_time.ms());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001368 }
Stefan Holmer13181032016-07-29 14:48:54 +02001369 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001370
Bjorn Terelius068fc352019-02-13 22:38:25 +01001371 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001372 float y = bitrate_bps.value_or(0) / 1000;
1373 acked_time_series.points.emplace_back(x, y);
1374#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Björn Terelius251b0dc2019-11-11 21:00:18 +01001375 y = acknowledged_bitrate_estimator->bitrate()
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001376 .value_or(DataRate::Zero())
1377 .kbps();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001378 acked_estimate_time_series.points.emplace_back(x, y);
1379#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001380 ++rtcp_iterator;
1381 }
stefanc3de0332016-08-02 07:22:17 -07001382 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1383 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001384 ProcessInterval msg;
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001385 msg.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001386 observer.Update(goog_cc->OnProcessInterval(msg));
1387 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001388 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001389 if (observer.GetAndResetBitrateUpdated() ||
1390 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001391 uint32_t y = observer.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001392 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001393 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001394 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001395 }
1396 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1397 }
1398 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001399 plot->AppendTimeSeries(std::move(time_series));
1400 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001401 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001402
Bjorn Terelius068fc352019-02-13 22:38:25 +01001403 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1404 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001405 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001406 plot->SetTitle("Simulated send-side BWE behavior");
1407}
1408
1409void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001410 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001411 class RembInterceptingPacketRouter : public PacketRouter {
1412 public:
1413 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1414 uint32_t bitrate_bps) override {
1415 last_bitrate_bps_ = bitrate_bps;
1416 bitrate_updated_ = true;
1417 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1418 }
1419 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1420 bool GetAndResetBitrateUpdated() {
1421 bool bitrate_updated = bitrate_updated_;
1422 bitrate_updated_ = false;
1423 return bitrate_updated;
1424 }
1425
1426 private:
1427 uint32_t last_bitrate_bps_;
1428 bool bitrate_updated_;
1429 };
1430
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001431 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001432
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001433 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1434 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1435 for (const auto& rtp_packet : stream.incoming_packets)
1436 incoming_rtp.insert(
1437 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001438 }
1439 }
1440
1441 SimulatedClock clock(0);
1442 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001443 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001444 // Is this intentional?
1445 ReceiveSideCongestionController rscc(&clock, &packet_router);
1446 // TODO(holmer): Log the call config and use that here instead.
1447 // static const uint32_t kDefaultStartBitrateBps = 300000;
1448 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1449
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001450 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1451 PointStyle::kHighlight);
1452 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001453
1454 RateStatistics acked_bitrate(250, 8000);
1455 int64_t last_update_us = 0;
1456 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001457 const RtpPacketType& packet = *kv.second;
1458 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1459 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1460 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001461 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001462 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001463 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001464 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001465 if (bitrate_bps) {
1466 uint32_t y = *bitrate_bps / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001467 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001468 acked_time_series.points.emplace_back(x, y);
1469 }
1470 if (packet_router.GetAndResetBitrateUpdated() ||
1471 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1472 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001473 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001474 time_series.points.emplace_back(x, y);
1475 last_update_us = clock.TimeInMicroseconds();
1476 }
1477 }
1478 // Add the data set to the plot.
1479 plot->AppendTimeSeries(std::move(time_series));
1480 plot->AppendTimeSeries(std::move(acked_time_series));
1481
Bjorn Terelius068fc352019-02-13 22:38:25 +01001482 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1483 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001484 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1485 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001486}
1487
tereliuse34c19c2016-08-15 08:47:14 -07001488void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001489 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001490 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001491 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1492 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001493
stefana0a8ed72017-09-06 02:06:32 -07001494 int64_t prev_y = 0;
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001495 std::vector<MatchedSendArrivalTimes> matched_rtp_rtcp =
1496 GetNetworkTrace(parsed_log_);
1497 absl::c_stable_sort(matched_rtp_rtcp, [](const MatchedSendArrivalTimes& a,
1498 const MatchedSendArrivalTimes& b) {
philipel3574d052019-11-18 14:38:13 +01001499 return a.feedback_arrival_time_ms < b.feedback_arrival_time_ms ||
1500 (a.feedback_arrival_time_ms == b.feedback_arrival_time_ms &&
1501 a.arrival_time_ms < b.arrival_time_ms);
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001502 });
1503 for (const auto& packet : matched_rtp_rtcp) {
Sebastian Jansson74f96ec2019-10-29 12:57:54 +01001504 if (packet.arrival_time_ms == MatchedSendArrivalTimes::kNotReceived)
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001505 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001506 float x = config_.GetCallTimeSec(1000 * packet.feedback_arrival_time_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001507 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1508 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001509 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1510 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1511 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001512 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001513 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001514
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001515 // We assume that the base network delay (w/o queues) is equal to half
1516 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
Mirko Bonadei604e75c2019-07-25 11:55:47 +02001517 // observed 1-ways delay and add half the minimum RTT.
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001518 const int64_t estimated_clock_offset_ms =
1519 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001520 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001521 point.y -= estimated_clock_offset_ms;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001522
stefanc3de0332016-08-02 07:22:17 -07001523 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001524 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
stefanc3de0332016-08-02 07:22:17 -07001525
Bjorn Terelius068fc352019-02-13 22:38:25 +01001526 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1527 "Time (s)", kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001528 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +01001529 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001530}
stefan08383272016-12-20 08:51:52 -08001531
Bjorn Terelius0295a962017-10-25 17:42:41 +02001532void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001533 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1534 const std::vector<LoggedRtpPacketOutgoing>& packets =
1535 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001536
Konrad Hofbauerbfb735b2019-04-16 11:12:11 +02001537 if (IsRtxSsrc(kOutgoingPacket, stream.ssrc)) {
1538 continue;
1539 }
1540
Bjorn Terelius0295a962017-10-25 17:42:41 +02001541 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001542 RTC_LOG(LS_WARNING)
1543 << "Can't estimate a the RTP clock frequency or the "
1544 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001545 continue;
1546 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001547 int64_t end_time_us = log_segments_.empty()
1548 ? std::numeric_limits<int64_t>::max()
1549 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001550 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001551 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001552 if (!estimated_frequency)
1553 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001554 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1555 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001556 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001557 << "Video stream should use a 90 kHz clock but appears to use "
1558 << *estimated_frequency / 1000 << ". Discarding.";
1559 continue;
1560 }
1561
1562 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001563 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001564 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001565 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001566 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1567 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001568 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1569 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1570 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001571 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001572 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001573 first_capture_timestamp) /
1574 *estimated_frequency * 1000;
1575 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001576 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1577 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001578 float x = config_.GetCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001579 float y = send_time_ms - capture_time_ms;
1580 pacer_delay_series.points.emplace_back(x, y);
1581 }
1582 plot->AppendTimeSeries(std::move(pacer_delay_series));
1583 }
1584
Bjorn Terelius068fc352019-02-13 22:38:25 +01001585 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1586 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001587 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1588 plot->SetTitle(
1589 "Delay from capture to send time. (First packet normalized to 0.)");
1590}
1591
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001592void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1593 Plot* plot) {
1594 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1595 TimeSeries rtp_timestamps(
1596 GetStreamName(direction, stream.ssrc) + " capture-time",
1597 LineStyle::kLine, PointStyle::kHighlight);
1598 for (const auto& packet : stream.packet_view) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001599 float x = config_.GetCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001600 float y = packet.header.timestamp;
1601 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001602 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001603 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001604
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001605 TimeSeries rtcp_timestamps(
1606 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1607 LineStyle::kLine, PointStyle::kHighlight);
1608 // TODO(terelius): Why only sender reports?
1609 const auto& sender_reports = parsed_log_.sender_reports(direction);
1610 for (const auto& rtcp : sender_reports) {
1611 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1612 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001613 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001614 float y = rtcp.sr.rtp_timestamp();
1615 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001616 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001617 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001618 }
1619
Bjorn Terelius068fc352019-02-13 22:38:25 +01001620 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1621 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001622 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1623 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001624}
michaelt6e5b2192017-02-22 07:33:27 -08001625
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001626void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1627 PacketDirection direction,
1628 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1629 std::string title,
1630 std::string yaxis_label,
1631 Plot* plot) {
1632 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1633 const auto& sender_reports = parsed_log_.sender_reports(direction);
1634 for (const auto& rtcp : sender_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001635 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001636 uint32_t ssrc = rtcp.sr.sender_ssrc();
1637 for (const auto& block : rtcp.sr.report_blocks()) {
1638 float y = fy(block);
1639 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1640 bool inserted;
1641 if (sr_report_it == sr_reports_by_ssrc.end()) {
1642 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1643 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1644 LineStyle::kLine, PointStyle::kHighlight));
1645 }
1646 sr_report_it->second.points.emplace_back(x, y);
1647 }
1648 }
1649 for (auto& kv : sr_reports_by_ssrc) {
1650 plot->AppendTimeSeries(std::move(kv.second));
1651 }
1652
1653 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1654 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1655 for (const auto& rtcp : receiver_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001656 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001657 uint32_t ssrc = rtcp.rr.sender_ssrc();
1658 for (const auto& block : rtcp.rr.report_blocks()) {
1659 float y = fy(block);
1660 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1661 bool inserted;
1662 if (rr_report_it == rr_reports_by_ssrc.end()) {
1663 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1664 ssrc,
1665 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1666 LineStyle::kLine, PointStyle::kHighlight));
1667 }
1668 rr_report_it->second.points.emplace_back(x, y);
1669 }
1670 }
1671 for (auto& kv : rr_reports_by_ssrc) {
1672 plot->AppendTimeSeries(std::move(kv.second));
1673 }
1674
Bjorn Terelius068fc352019-02-13 22:38:25 +01001675 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1676 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001677 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1678 plot->SetTitle(title);
1679}
1680
michaelt6e5b2192017-02-22 07:33:27 -08001681void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001682 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1683 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001684 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001685 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001686 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001687 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001688 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001689 return absl::nullopt;
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, GetAnaBitrateBps,
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, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1701 plot->SetTitle("Reported audio encoder target bitrate");
1702}
1703
1704void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001705 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1706 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001707 auto GetAnaFrameLengthMs =
1708 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001709 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001710 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001711 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001712 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001713 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001714 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001715 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001716 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001717 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001718 ToCallTime, GetAnaFrameLengthMs,
1719 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001720 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001721 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1722 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001723 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1724 plot->SetTitle("Reported audio encoder frame length");
1725}
1726
terelius2ee076d2017-08-15 02:04:02 -07001727void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001728 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001729 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001730 auto GetAnaPacketLoss =
1731 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001732 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001733 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001734 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001735 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001736 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001737 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001738 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001739 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001740 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001741 ToCallTime, GetAnaPacketLoss,
1742 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001743 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001744 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1745 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001746 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1747 kTopMargin);
1748 plot->SetTitle("Reported audio encoder lost packets");
1749}
1750
1751void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001752 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1753 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001754 auto GetAnaFecEnabled =
1755 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001756 if (ana_event.config.enable_fec)
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.enable_fec));
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, GetAnaFecEnabled,
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, "FEC (false/true)", kBottomMargin, kTopMargin);
1771 plot->SetTitle("Reported audio encoder FEC");
1772}
1773
1774void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001775 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1776 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001777 auto GetAnaDtxEnabled =
1778 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001779 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001780 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001781 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001782 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001783 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001784 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001785 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001786 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001787 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001788 ToCallTime, GetAnaDtxEnabled,
1789 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001790 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001791 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1792 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001793 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1794 plot->SetTitle("Reported audio encoder DTX");
1795}
1796
1797void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001798 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1799 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001800 auto GetAnaNumChannels =
1801 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001802 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001803 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001804 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001805 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001806 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001807 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001808 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001809 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001810 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001811 ToCallTime, GetAnaNumChannels,
1812 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001813 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001814 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1815 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001816 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1817 kBottomMargin, kTopMargin);
1818 plot->SetTitle("Reported audio encoder number of channels");
1819}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001820
1821class NetEqStreamInput : public test::NetEqInput {
1822 public:
1823 // Does not take any ownership, and all pointers must refer to valid objects
1824 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001825 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001826 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001827 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001828 : packet_stream_(*packet_stream),
1829 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001830 output_events_it_(output_events->begin()),
1831 output_events_end_(output_events->end()),
1832 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001833 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001834 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001835 }
1836
Danil Chapovalov431abd92018-06-18 12:54:17 +02001837 absl::optional<int64_t> NextPacketTime() 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 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001841 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001842 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001843 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001844 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001845 }
1846
Danil Chapovalov431abd92018-06-18 12:54:17 +02001847 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001848 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001849 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001850 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001851 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001852 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001853 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001854 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001855 }
1856
1857 std::unique_ptr<PacketData> PopPacket() override {
1858 if (packet_stream_it_ == packet_stream_.end()) {
1859 return std::unique_ptr<PacketData>();
1860 }
1861 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001862 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001863 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001864
1865 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1866 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001867 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1868 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001869 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1870
1871 ++packet_stream_it_;
1872 return packet_data;
1873 }
1874
1875 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001876 if (output_events_it_ != output_events_end_) {
1877 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001878 }
1879 }
1880
1881 bool ended() const override { return !NextEventTime(); }
1882
Danil Chapovalov431abd92018-06-18 12:54:17 +02001883 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001884 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001885 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001886 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001887 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001888 }
1889
1890 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001891 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1892 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001893 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1894 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001895 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001896};
1897
1898namespace {
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001899
1900// Factory to create a "replacement decoder" that produces the decoded audio
1901// by reading from a file rather than from the encoded payloads.
1902class ReplacementAudioDecoderFactory : public AudioDecoderFactory {
1903 public:
1904 ReplacementAudioDecoderFactory(const absl::string_view replacement_file_name,
1905 int file_sample_rate_hz)
1906 : replacement_file_name_(replacement_file_name),
1907 file_sample_rate_hz_(file_sample_rate_hz) {}
1908
1909 std::vector<AudioCodecSpec> GetSupportedDecoders() override {
1910 RTC_NOTREACHED();
1911 return {};
1912 }
1913
1914 bool IsSupportedDecoder(const SdpAudioFormat& format) override {
1915 return true;
1916 }
1917
1918 std::unique_ptr<AudioDecoder> MakeAudioDecoder(
1919 const SdpAudioFormat& format,
1920 absl::optional<AudioCodecPairId> codec_pair_id) override {
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001921 auto replacement_file = std::make_unique<test::ResampleInputAudioFile>(
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001922 replacement_file_name_, file_sample_rate_hz_);
1923 replacement_file->set_output_rate_hz(48000);
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001924 return std::make_unique<test::FakeDecodeFromFile>(
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001925 std::move(replacement_file), 48000, false);
1926 }
1927
1928 private:
1929 const std::string replacement_file_name_;
1930 const int file_sample_rate_hz_;
1931};
1932
henrik.lundin3c938fc2017-06-14 06:09:58 -07001933// Creates a NetEq test object and all necessary input and output helpers. Runs
1934// the test and returns the NetEqDelayAnalyzer object that was used to
1935// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001936std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001937 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001938 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001939 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001940 const std::string& replacement_file_name,
1941 int file_sample_rate_hz) {
1942 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001943 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001944
1945 constexpr int kReplacementPt = 127;
1946 std::set<uint8_t> cn_types;
1947 std::set<uint8_t> forbidden_types;
1948 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1949 cn_types, forbidden_types));
1950
1951 NetEq::Config config;
1952 config.max_packets_in_buffer = 200;
1953 config.enable_fast_accelerate = true;
1954
1955 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1956
Niels Möller3f651d82018-12-19 15:06:17 +01001957 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001958 new rtc::RefCountedObject<ReplacementAudioDecoderFactory>(
1959 replacement_file_name, file_sample_rate_hz);
Niels Möller3f651d82018-12-19 15:06:17 +01001960
Niels Möller05543682019-01-10 16:55:06 +01001961 test::NetEqTest::DecoderMap codecs = {
1962 {kReplacementPt, SdpAudioFormat("l16", 48000, 1)}};
henrik.lundin3c938fc2017-06-14 06:09:58 -07001963
1964 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1965 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001966 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1967 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001968 test::DefaultNetEqTestErrorCallback error_cb;
1969 test::NetEqTest::Callbacks callbacks;
1970 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001971 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1972 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001973
Ivo Creusencee751a2020-01-16 17:17:09 +01001974 test::NetEqTest test(config, decoder_factory, codecs, /*text_log=*/nullptr,
1975 /*factory=*/nullptr, std::move(input), std::move(output),
1976 callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001977 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001978 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001979}
1980} // namespace
1981
Minyue Lic6ff7572018-05-04 09:46:44 +02001982EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001983 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001984 int file_sample_rate_hz) const {
1985 NetEqStatsGetterMap neteq_stats;
1986
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001987 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001988 const uint32_t ssrc = stream.ssrc;
1989 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1990 continue;
1991 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1992 &stream.incoming_packets;
1993 if (audio_packets == nullptr) {
1994 // No incoming audio stream found.
1995 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001996 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001997
Minyue Li27e2b7d2018-05-07 15:20:24 +02001998 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1999
2000 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
2001 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
2002 if (output_events_it == parsed_log_.audio_playout_events().end()) {
2003 // Could not find output events with SSRC matching the input audio stream.
2004 // Using the first available stream of output events.
2005 output_events_it = parsed_log_.audio_playout_events().cbegin();
2006 }
2007
Danil Chapovalov431abd92018-06-18 12:54:17 +02002008 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02002009 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02002010 ? absl::nullopt
2011 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002012
2013 neteq_stats[ssrc] = CreateNetEqTestAndRun(
2014 audio_packets, &output_events_it->second, end_time_ms,
2015 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002016 }
2017
Minyue Lic6ff7572018-05-04 09:46:44 +02002018 return neteq_stats;
2019}
2020
Minyue Lic97933f2018-08-10 12:51:15 +02002021// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
2022// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02002023void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02002024 uint32_t ssrc,
2025 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02002026 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02002027 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
2028 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
2029 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
2030 test::NetEqDelayAnalyzer::Delays target_delay_ms;
2031
Minyue Li01d2a672018-06-21 21:17:19 +02002032 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02002033 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
2034 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002035
Minyue Lic97933f2018-08-10 12:51:15 +02002036 TimeSeries time_series_packet_arrival("packet arrival delay",
2037 LineStyle::kLine);
2038 TimeSeries time_series_relative_packet_arrival(
2039 "Relative packet arrival delay", LineStyle::kLine);
2040 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
2041 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
2042 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02002043
2044 for (const auto& data : arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002045 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002046 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002047 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002048 }
2049 for (const auto& data : corrected_arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002050 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002051 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002052 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02002053 TimeSeriesPoint(x, y));
2054 }
2055 for (const auto& data : playout_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002056 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002057 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002058 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002059 }
2060 for (const auto& data : target_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002061 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002062 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002063 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002064 }
2065
Minyue Lic97933f2018-08-10 12:51:15 +02002066 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
2067 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
2068 plot->AppendTimeSeries(std::move(time_series_play_time));
2069 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002070
Bjorn Terelius068fc352019-02-13 22:38:25 +01002071 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2072 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002073 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
2074 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002075 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
2076}
2077
Minyue Lic9ac93f2018-06-26 13:01:32 +02002078template <typename NetEqStatsType>
2079void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02002080 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02002081 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
2082 const test::NetEqStatsGetter*)> data_extractor,
2083 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02002084 const std::string& plot_name,
2085 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02002086 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02002087
2088 for (const auto& st : neteq_stats) {
2089 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02002090 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
2091 data_extractor(st.second.get());
2092 for (const auto& data : *data_vector) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002093 const float time =
2094 config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Lic9ac93f2018-06-26 13:01:32 +02002095 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002096 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02002097 }
2098 }
2099
2100 for (auto& series : time_series) {
2101 series.second.label = GetStreamName(kIncomingPacket, series.first);
2102 series.second.line_style = LineStyle::kLine;
2103 plot->AppendTimeSeries(std::move(series.second));
2104 }
2105
Bjorn Terelius068fc352019-02-13 22:38:25 +01002106 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2107 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002108 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002109 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002110}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002111
Minyue Lic9ac93f2018-06-26 13:01:32 +02002112void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
2113 const NetEqStatsGetterMap& neteq_stats,
2114 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
2115 const std::string& plot_name,
2116 Plot* plot) const {
2117 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
2118 neteq_stats,
2119 [](const test::NetEqStatsGetter* stats_getter) {
2120 return stats_getter->stats();
2121 },
2122 stats_extractor, plot_name, plot);
2123}
2124
2125void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
2126 const NetEqStatsGetterMap& neteq_stats,
2127 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
2128 const std::string& plot_name,
2129 Plot* plot) const {
2130 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
2131 neteq_stats,
2132 [](const test::NetEqStatsGetter* stats_getter) {
2133 return stats_getter->lifetime_stats();
2134 },
2135 stats_extractor, plot_name, plot);
2136}
2137
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002138void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
2139 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002140 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002141 if (configs_by_cp_id.find(config.candidate_pair_id) ==
2142 configs_by_cp_id.end()) {
2143 const std::string candidate_pair_desc =
2144 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08002145 configs_by_cp_id[config.candidate_pair_id] =
2146 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
2147 candidate_pair_desc,
2148 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002149 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2150 candidate_pair_desc;
2151 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002152 float x = config_.GetCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002153 float y = static_cast<float>(config.type);
2154 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
2155 }
2156
2157 // TODO(qingsi): There can be a large number of candidate pairs generated by
2158 // certain calls and the frontend cannot render the chart in this case due to
2159 // the failure of generating a palette with the same number of colors.
2160 for (auto& kv : configs_by_cp_id) {
2161 plot->AppendTimeSeries(std::move(kv.second));
2162 }
2163
Bjorn Terelius068fc352019-02-13 22:38:25 +01002164 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2165 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002166 plot->SetSuggestedYAxis(0, 3, "Config Type", kBottomMargin, kTopMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002167 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002168 plot->SetYAxisTickLabels(
2169 {{static_cast<float>(IceCandidatePairConfigType::kAdded), "ADDED"},
2170 {static_cast<float>(IceCandidatePairConfigType::kUpdated), "UPDATED"},
2171 {static_cast<float>(IceCandidatePairConfigType::kDestroyed),
2172 "DESTROYED"},
2173 {static_cast<float>(IceCandidatePairConfigType::kSelected),
2174 "SELECTED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002175}
2176
2177std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
2178 uint32_t candidate_pair_id) {
2179 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
2180 candidate_pair_desc_by_id_.end()) {
2181 return candidate_pair_desc_by_id_[candidate_pair_id];
2182 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002183 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002184 // TODO(qingsi): Add the handling of the "Updated" config event after the
2185 // visualization of property change for candidate pairs is introduced.
2186 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
2187 candidate_pair_desc_by_id_.end()) {
2188 const std::string candidate_pair_desc =
2189 GetCandidatePairLogDescriptionAsString(config);
2190 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2191 candidate_pair_desc;
2192 }
2193 }
2194 return candidate_pair_desc_by_id_[candidate_pair_id];
2195}
2196
2197void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002198 constexpr int kEventTypeOffset =
2199 static_cast<int>(IceCandidatePairConfigType::kNumValues);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002200 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002201 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002202 if (checks_by_cp_id.find(event.candidate_pair_id) ==
2203 checks_by_cp_id.end()) {
2204 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08002205 "[" + std::to_string(event.candidate_pair_id) + "]" +
2206 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002207 LineStyle::kNone, PointStyle::kHighlight);
2208 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002209 float x = config_.GetCallTimeSec(event.log_time_us());
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002210 float y = static_cast<float>(event.type) + kEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002211 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2212 }
2213
2214 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2215 for (auto& kv : checks_by_cp_id) {
2216 plot->AppendTimeSeries(std::move(kv.second));
2217 }
2218
Bjorn Terelius068fc352019-02-13 22:38:25 +01002219 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2220 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002221 plot->SetSuggestedYAxis(0, 4, "Connectivity State", kBottomMargin,
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002222 kTopMargin);
2223 plot->SetTitle("[IceEventLog] ICE connectivity checks");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002224
2225 plot->SetYAxisTickLabels(
2226 {{static_cast<float>(IceCandidatePairEventType::kCheckSent) +
2227 kEventTypeOffset,
2228 "CHECK SENT"},
2229 {static_cast<float>(IceCandidatePairEventType::kCheckReceived) +
2230 kEventTypeOffset,
2231 "CHECK RECEIVED"},
2232 {static_cast<float>(IceCandidatePairEventType::kCheckResponseSent) +
2233 kEventTypeOffset,
2234 "RESPONSE SENT"},
2235 {static_cast<float>(IceCandidatePairEventType::kCheckResponseReceived) +
2236 kEventTypeOffset,
2237 "RESPONSE RECEIVED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002238}
2239
Zach Stein10a58012018-12-07 12:26:28 -08002240void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
2241 TimeSeries states("DTLS Transport State", LineStyle::kNone,
2242 PointStyle::kHighlight);
2243 for (const auto& event : parsed_log_.dtls_transport_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002244 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002245 float y = static_cast<float>(event.dtls_transport_state);
2246 states.points.emplace_back(x, y);
2247 }
2248 plot->AppendTimeSeries(std::move(states));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002249 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2250 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002251 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002252 "Transport State", kBottomMargin, kTopMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002253 plot->SetTitle("DTLS Transport State");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002254 plot->SetYAxisTickLabels(
2255 {{static_cast<float>(DtlsTransportState::kNew), "NEW"},
2256 {static_cast<float>(DtlsTransportState::kConnecting), "CONNECTING"},
2257 {static_cast<float>(DtlsTransportState::kConnected), "CONNECTED"},
2258 {static_cast<float>(DtlsTransportState::kClosed), "CLOSED"},
2259 {static_cast<float>(DtlsTransportState::kFailed), "FAILED"}});
Zach Stein10a58012018-12-07 12:26:28 -08002260}
2261
2262void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2263 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2264 PointStyle::kHighlight);
2265 for (const auto& event : parsed_log_.dtls_writable_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002266 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002267 float y = static_cast<float>(event.writable);
2268 writable.points.emplace_back(x, y);
2269 }
2270 plot->AppendTimeSeries(std::move(writable));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002271 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2272 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002273 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2274 plot->SetTitle("DTLS Writable State");
2275}
2276
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002277void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002278 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002279 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2280 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2281 }
2282 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2283 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2284 }
2285 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2286 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2287 }
2288 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2289 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2290 }
2291 for (const auto& alert : incoming_seq_num_jumps_) {
2292 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2293 }
2294 for (const auto& alert : incoming_capture_time_jumps_) {
2295 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2296 }
2297 for (const auto& alert : outgoing_seq_num_jumps_) {
2298 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2299 }
2300 for (const auto& alert : outgoing_capture_time_jumps_) {
2301 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2302 }
2303 for (const auto& alert : outgoing_high_loss_alerts_) {
2304 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002305 }
2306 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2307}
2308
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002309void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2310 // With 100 packets/s (~800kbps), false positives would require 10 s without
2311 // data.
2312 constexpr int64_t kMaxSeqNumJump = 1000;
2313 // With a 90 kHz clock, false positives would require 10 s without data.
2314 constexpr int64_t kMaxCaptureTimeJump = 900000;
2315
2316 int64_t end_time_us = log_segments_.empty()
2317 ? std::numeric_limits<int64_t>::max()
2318 : log_segments_.front().second;
2319
2320 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002321 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002322 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002323 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002324 // Check for gaps in sequence numbers and capture timestamps.
2325 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2326 for (const auto& packet : stream.packet_view) {
2327 if (packet.log_time_us() > end_time_us) {
2328 // Only process the first (LOG_START, LOG_END) segment.
2329 break;
2330 }
2331
2332 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2333 if (last_seq_num.has_value() &&
2334 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002335 Alert_SeqNumJump(direction,
2336 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002337 packet.header.ssrc);
2338 }
2339 last_seq_num.emplace(seq_num);
2340
2341 int64_t capture_time =
2342 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2343 if (last_capture_time.has_value() &&
2344 std::abs(capture_time - last_capture_time.value()) >
2345 kMaxCaptureTimeJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002346 Alert_CaptureTimeJump(direction,
2347 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002348 packet.header.ssrc);
2349 }
2350 last_capture_time.emplace(capture_time);
2351 }
2352 }
2353}
2354
2355void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2356 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2357 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2358 int64_t end_time_us = log_segments_.empty()
2359 ? std::numeric_limits<int64_t>::max()
2360 : log_segments_.front().second;
2361
2362 // TODO(terelius): The parser could provide a list of all packets, ordered
2363 // by time, for each direction.
2364 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2365 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2366 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2367 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2368 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002369 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002370 for (const auto& kv : rtp_in_direction) {
2371 int64_t timestamp = kv.first;
2372 if (timestamp > end_time_us) {
2373 // Only process the first (LOG_START, LOG_END) segment.
2374 break;
2375 }
2376 int64_t duration = timestamp - last_rtp_time.value_or(0);
2377 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2378 // No packet sent/received for more than 500 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002379 Alert_RtpLogTimeGap(direction, config_.GetCallTimeSec(timestamp),
2380 duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002381 }
2382 last_rtp_time.emplace(timestamp);
2383 }
2384
Danil Chapovalov431abd92018-06-18 12:54:17 +02002385 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002386 if (direction == kIncomingPacket) {
2387 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2388 if (rtcp.log_time_us() > end_time_us) {
2389 // Only process the first (LOG_START, LOG_END) segment.
2390 break;
2391 }
2392 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2393 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2394 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002395 Alert_RtcpLogTimeGap(direction,
2396 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002397 duration / 1000);
2398 }
2399 last_rtcp_time.emplace(rtcp.log_time_us());
2400 }
2401 } else {
2402 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2403 if (rtcp.log_time_us() > end_time_us) {
2404 // Only process the first (LOG_START, LOG_END) segment.
2405 break;
2406 }
2407 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2408 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2409 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002410 Alert_RtcpLogTimeGap(direction,
2411 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002412 duration / 1000);
2413 }
2414 last_rtcp_time.emplace(rtcp.log_time_us());
2415 }
2416 }
2417}
2418
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002419// TODO(terelius): Notifications could possibly be generated by the same code
2420// that produces the graphs. There is some code duplication that could be
2421// avoided, but that might be solved anyway when we move functionality from the
2422// analyzer to the parser.
2423void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002424 CreateStreamGapAlerts(kIncomingPacket);
2425 CreateStreamGapAlerts(kOutgoingPacket);
2426 CreateTransmissionGapAlerts(kIncomingPacket);
2427 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002428
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002429 int64_t end_time_us = log_segments_.empty()
2430 ? std::numeric_limits<int64_t>::max()
2431 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002432
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002433 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002434 // Loss feedback
2435 int64_t total_lost_packets = 0;
2436 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002437 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2438 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002439 // Only process the first (LOG_START, LOG_END) segment.
2440 break;
2441 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002442 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002443 bwe_update.expected_packets;
2444 total_lost_packets += lost_packets;
2445 total_expected_packets += bwe_update.expected_packets;
2446 }
2447 double avg_outgoing_loss =
2448 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002449 if (avg_outgoing_loss > kMaxLossFraction) {
2450 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002451 }
2452}
2453
terelius54ce6802016-07-13 06:44:41 -07002454} // namespace webrtc