blob: 106e8daa9f50d8cd76f8ec3b1be8f5c271565860 [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
terelius54ce6802016-07-13 06:44:41 -0700620// For each SSRC, plot the time between the consecutive playouts.
621void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200622 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
623 uint32_t ssrc = playout_stream.first;
624 if (!MatchingSsrc(ssrc, desired_ssrc_))
625 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200626 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200627 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200628 for (const auto& playout_event : playout_stream.second) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100629 float x = config_.GetCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200630 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200631 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200632 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200633 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200634 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700635 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200636 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700637 }
638
Bjorn Terelius068fc352019-02-13 22:38:25 +0100639 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
640 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700641 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
642 kTopMargin);
643 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700644}
645
ivocaac9d6f2016-09-22 07:01:47 -0700646// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200647void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
648 Plot* plot) {
649 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
650 if (!IsAudioSsrc(direction, stream.ssrc))
651 continue;
652 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
653 LineStyle::kLine);
654 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700655 if (packet.header.extension.hasAudioLevel) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100656 float x = config_.GetCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700657 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
658 // Here we convert it to dBov.
659 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200660 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700661 }
662 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200663 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700664 }
665
Bjorn Terelius068fc352019-02-13 22:38:25 +0100666 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
667 "Time (s)", kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200668 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200669 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700670}
671
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100672// For each SSRC, plot the sequence number difference between consecutive
673// incoming packets.
terelius54ce6802016-07-13 06:44:41 -0700674void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200675 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
676 // Filter on SSRC.
677 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700678 continue;
terelius54ce6802016-07-13 06:44:41 -0700679 }
terelius54ce6802016-07-13 06:44:41 -0700680
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200681 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
682 LineStyle::kBar);
683 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
684 const LoggedRtpPacketIncoming& new_packet) {
685 int64_t diff =
686 WrappingDifference(new_packet.rtp.header.sequenceNumber,
687 old_packet.rtp.header.sequenceNumber, 1ul << 16);
688 return diff;
689 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200690 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100691 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200692 };
693 ProcessPairs<LoggedRtpPacketIncoming, float>(
694 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
695 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700696 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700697 }
698
Bjorn Terelius068fc352019-02-13 22:38:25 +0100699 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
700 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700701 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
702 kTopMargin);
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100703 plot->SetTitle("Incoming sequence number delta");
terelius54ce6802016-07-13 06:44:41 -0700704}
705
Stefan Holmer99f8e082016-09-09 13:37:50 +0200706void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200707 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
708 const std::vector<LoggedRtpPacketIncoming>& packets =
709 stream.incoming_packets;
710 // Filter on SSRC.
Mirko Bonadei1f173152019-07-25 15:28:14 +0200711 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.empty()) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200712 continue;
713 }
714
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200715 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
716 LineStyle::kLine, PointStyle::kHighlight);
717 // TODO(terelius): Should the window and step size be read from the class
718 // instead?
719 const int64_t kWindowUs = 1000000;
720 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100721 SeqNumUnwrapper<uint16_t> unwrapper_;
722 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800723 size_t window_index_begin = 0;
724 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200725 uint64_t highest_seq_number =
726 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
727 uint64_t highest_prior_seq_number =
728 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800729
Bjorn Terelius068fc352019-02-13 22:38:25 +0100730 for (int64_t t = config_.begin_time_; t < config_.end_time_ + kStep;
731 t += kStep) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200732 while (window_index_end < packets.size() &&
733 packets[window_index_end].rtp.log_time_us() < t) {
734 uint64_t sequence_number = unwrapper_.Unwrap(
735 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800736 highest_seq_number = std::max(highest_seq_number, sequence_number);
737 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200738 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200739 while (window_index_begin < packets.size() &&
740 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
741 uint64_t sequence_number = prior_unwrapper_.Unwrap(
742 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800743 highest_prior_seq_number =
744 std::max(highest_prior_seq_number, sequence_number);
745 ++window_index_begin;
746 }
Bjorn Terelius068fc352019-02-13 22:38:25 +0100747 float x = config_.GetCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200748 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800749 if (expected_packets > 0) {
750 int64_t received_packets = window_index_end - window_index_begin;
751 int64_t lost_packets = expected_packets - received_packets;
752 float y = static_cast<float>(lost_packets) / expected_packets * 100;
753 time_series.points.emplace_back(x, y);
754 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200755 }
philipel35ba9bd2017-04-19 05:58:51 -0700756 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200757 }
758
Bjorn Terelius068fc352019-02-13 22:38:25 +0100759 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
760 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100761 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
762 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
Stefan Holmer99f8e082016-09-09 13:37:50 +0200763}
764
terelius2ee076d2017-08-15 02:04:02 -0700765void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100766 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200767 // Filter on SSRC.
768 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200769 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700770 continue;
771 }
terelius54ce6802016-07-13 06:44:41 -0700772
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100773 const std::vector<LoggedRtpPacketIncoming>& packets =
774 stream.incoming_packets;
775 if (packets.size() < 100) {
776 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
777 << packets.size() << " packets in the stream.";
778 continue;
779 }
780 int64_t end_time_us = log_segments_.empty()
781 ? std::numeric_limits<int64_t>::max()
782 : log_segments_.front().second;
783 absl::optional<uint32_t> estimated_frequency =
784 EstimateRtpClockFrequency(packets, end_time_us);
785 if (!estimated_frequency)
786 continue;
787 const double frequency_hz = *estimated_frequency;
788 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
789 RTC_LOG(LS_WARNING)
790 << "Video stream should use a 90 kHz clock but appears to use "
791 << frequency_hz / 1000 << ". Discarding.";
792 continue;
793 }
794
795 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100796 return this->config_.GetCallTimeSec(packet.log_time_us());
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100797 };
798 auto ToNetworkDelay = [frequency_hz](
799 const LoggedRtpPacketIncoming& old_packet,
800 const LoggedRtpPacketIncoming& new_packet) {
801 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
802 };
803
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200804 TimeSeries capture_time_data(
805 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
806 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100807 AccumulatePairs<LoggedRtpPacketIncoming, double>(
808 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700809 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700810
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200811 TimeSeries send_time_data(
812 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
813 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100814 AccumulatePairs<LoggedRtpPacketIncoming, double>(
815 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
816 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700817 }
818
Bjorn Terelius068fc352019-02-13 22:38:25 +0100819 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
820 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +0100821 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
822 plot->SetTitle("Incoming network delay (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700823}
824
tereliusf736d232016-08-04 10:00:11 -0700825// Plot the fraction of packets lost (as perceived by the loss-based BWE).
826void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100827 TimeSeries time_series("Fraction lost", LineStyle::kLine,
828 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200829 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100830 float x = config_.GetCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200831 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700832 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700833 }
tereliusf736d232016-08-04 10:00:11 -0700834
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200835 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +0100836 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
837 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100838 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
839 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
tereliusf736d232016-08-04 10:00:11 -0700840}
841
terelius54ce6802016-07-13 06:44:41 -0700842// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200843void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
844 // TODO(terelius): This could be provided by the parser.
845 std::multimap<int64_t, size_t> packets_in_order;
846 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
847 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
848 packets_in_order.insert(
849 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700850 }
851
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200852 auto window_begin = packets_in_order.begin();
853 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700854 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700855
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800856 if (!packets_in_order.empty()) {
857 // Calculate a moving average of the bitrate and store in a TimeSeries.
858 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
859 for (int64_t time = config_.begin_time_;
860 time < config_.end_time_ + config_.step_; time += config_.step_) {
861 while (window_end != packets_in_order.end() && window_end->first < time) {
862 bytes_in_window += window_end->second;
863 ++window_end;
864 }
865 while (window_begin != packets_in_order.end() &&
866 window_begin->first < time - config_.window_duration_) {
867 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
868 bytes_in_window -= window_begin->second;
869 ++window_begin;
870 }
871 float window_duration_in_seconds =
872 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
873 float x = config_.GetCallTimeSec(time);
874 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
875 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700876 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800877 plot->AppendTimeSeries(std::move(bitrate_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200878 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200879
880 // Overlay the outgoing REMB over incoming bitrate.
881 TimeSeries remb_series("Remb", LineStyle::kStep);
882 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100883 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200884 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
885 remb_series.points.emplace_back(x, y);
886 }
887 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
888
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800889 if (!parsed_log_.generic_packets_received().empty()) {
890 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
891 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
892 return packet.packet_length * 8.0 / 1000.0;
893 };
894 MovingAverage<LoggedGenericPacketReceived, double>(
895 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
896 &time_series);
897 plot->AppendTimeSeries(std::move(time_series));
898 }
899
Bjorn Terelius068fc352019-02-13 22:38:25 +0100900 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
901 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200902 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
903 plot->SetTitle("Incoming RTP bitrate");
904}
905
906// Plot the total bandwidth used by all RTP streams.
907void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
908 bool show_detector_state,
909 bool show_alr_state) {
910 // TODO(terelius): This could be provided by the parser.
911 std::multimap<int64_t, size_t> packets_in_order;
912 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
913 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
914 packets_in_order.insert(
915 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
916 }
917
918 auto window_begin = packets_in_order.begin();
919 auto window_end = packets_in_order.begin();
920 size_t bytes_in_window = 0;
921
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800922 if (!packets_in_order.empty()) {
923 // Calculate a moving average of the bitrate and store in a TimeSeries.
924 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
925 for (int64_t time = config_.begin_time_;
926 time < config_.end_time_ + config_.step_; time += config_.step_) {
927 while (window_end != packets_in_order.end() && window_end->first < time) {
928 bytes_in_window += window_end->second;
929 ++window_end;
930 }
931 while (window_begin != packets_in_order.end() &&
932 window_begin->first < time - config_.window_duration_) {
933 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
934 bytes_in_window -= window_begin->second;
935 ++window_begin;
936 }
937 float window_duration_in_seconds =
938 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
939 float x = config_.GetCallTimeSec(time);
940 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
941 bitrate_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200942 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800943 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700944 }
945
terelius8058e582016-07-25 01:32:41 -0700946 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200947 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
948 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100949 float x = config_.GetCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200950 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
951 loss_series.points.emplace_back(x, y);
952 }
philipel10fc0e62017-04-11 01:50:23 -0700953
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200954 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
955 IntervalSeries overusing_series("Overusing", "#ff8e82",
956 IntervalSeries::kHorizontal);
957 IntervalSeries underusing_series("Underusing", "#5092fc",
958 IntervalSeries::kHorizontal);
959 IntervalSeries normal_series("Normal", "#c4ffc4",
960 IntervalSeries::kHorizontal);
961 IntervalSeries* last_series = &normal_series;
962 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700963
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200964 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700965
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200966 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100967 float x = config_.GetCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200968 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700969
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200970 if (last_detector_state != delay_update.detector_state) {
971 last_series->intervals.emplace_back(last_detector_switch, x);
972 last_detector_state = delay_update.detector_state;
973 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700974
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200975 switch (delay_update.detector_state) {
976 case BandwidthUsage::kBwNormal:
977 last_series = &normal_series;
978 break;
979 case BandwidthUsage::kBwUnderusing:
980 last_series = &underusing_series;
981 break;
982 case BandwidthUsage::kBwOverusing:
983 last_series = &overusing_series;
984 break;
985 case BandwidthUsage::kLast:
986 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200987 }
988 }
philipel23c7f252017-07-14 06:30:03 -0700989
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200990 delay_series.points.emplace_back(x, y);
991 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200992
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200993 RTC_CHECK(last_series);
Bjorn Terelius068fc352019-02-13 22:38:25 +0100994 last_series->intervals.emplace_back(last_detector_switch, config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200995
996 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
997 PointStyle::kHighlight);
998 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100999 float x = config_.GetCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001000 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
1001 created_series.points.emplace_back(x, y);
1002 }
1003
1004 TimeSeries result_series("Probing results.", LineStyle::kNone,
1005 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001006 for (auto& result : parsed_log_.bwe_probe_success_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001007 float x = config_.GetCallTimeSec(result.log_time_us());
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001008 float y = static_cast<float>(result.bitrate_bps) / 1000;
1009 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001010 }
1011
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001012 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1013 PointStyle::kHighlight);
1014 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001015 float x = config_.GetCallTimeSec(failure.log_time_us());
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001016 probe_failures_series.points.emplace_back(x, 0);
1017 }
1018
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001019 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1020 bool previously_in_alr = false;
1021 int64_t alr_start = 0;
1022 for (auto& alr : parsed_log_.alr_state_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001023 float y = config_.GetCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001024 if (!previously_in_alr && alr.in_alr) {
1025 alr_start = alr.log_time_us();
1026 previously_in_alr = true;
1027 } else if (previously_in_alr && !alr.in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001028 float x = config_.GetCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +01001029 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001030 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +00001031 }
Björn Tereliusff612732018-04-25 14:23:01 +00001032 }
1033
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001034 if (previously_in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001035 float x = config_.GetCallTimeSec(alr_start);
1036 float y = config_.GetCallTimeSec(config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001037 alr_state.intervals.emplace_back(x, y);
1038 }
1039
1040 if (show_detector_state) {
1041 plot->AppendIntervalSeries(std::move(overusing_series));
1042 plot->AppendIntervalSeries(std::move(underusing_series));
1043 plot->AppendIntervalSeries(std::move(normal_series));
1044 }
1045
1046 if (show_alr_state) {
1047 plot->AppendIntervalSeries(std::move(alr_state));
1048 }
1049 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001050 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001051 plot->AppendTimeSeries(std::move(delay_series));
1052 plot->AppendTimeSeries(std::move(created_series));
1053 plot->AppendTimeSeries(std::move(result_series));
1054
1055 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001056 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001057 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001058 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001059 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001060 remb_series.points.emplace_back(x, y);
1061 }
1062 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1063
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001064 if (!parsed_log_.generic_packets_sent().empty()) {
1065 {
1066 TimeSeries time_series("Outgoing generic total bitrate",
1067 LineStyle::kLine);
1068 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1069 return packet.packet_length() * 8.0 / 1000.0;
1070 };
1071 MovingAverage<LoggedGenericPacketSent, double>(
1072 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1073 &time_series);
1074 plot->AppendTimeSeries(std::move(time_series));
1075 }
1076
1077 {
1078 TimeSeries time_series("Outgoing generic payload bitrate",
1079 LineStyle::kLine);
1080 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1081 return packet.payload_length * 8.0 / 1000.0;
1082 };
1083 MovingAverage<LoggedGenericPacketSent, double>(
1084 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1085 &time_series);
1086 plot->AppendTimeSeries(std::move(time_series));
1087 }
1088 }
1089
Bjorn Terelius068fc352019-02-13 22:38:25 +01001090 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1091 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001092 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001093 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001094}
1095
1096// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001097void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1098 Plot* plot) {
1099 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1100 // Filter on SSRC.
1101 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001102 continue;
terelius54ce6802016-07-13 06:44:41 -07001103 }
1104
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001105 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1106 LineStyle::kLine);
1107 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1108 return packet.total_length * 8.0 / 1000.0;
1109 };
terelius53dc23c2017-03-13 05:24:05 -07001110 MovingAverage<LoggedRtpPacket, double>(
Bjorn Terelius068fc352019-02-13 22:38:25 +01001111 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001112 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001113 }
1114
Bjorn Terelius068fc352019-02-13 22:38:25 +01001115 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1116 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001117 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001118 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001119}
1120
Bjorn Terelius9775a582019-02-15 17:29:58 +01001121// Plot the bitrate allocation for each temporal and spatial layer.
1122// Computed from RTCP XR target bitrate block, so the graph is only populated if
1123// those are sent.
1124void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1125 Plot* plot) {
1126 std::map<LayerDescription, TimeSeries> time_series;
1127 const auto& xr_list = parsed_log_.extended_reports(direction);
1128 for (const auto& rtcp : xr_list) {
1129 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1130 rtcp.xr.target_bitrate();
1131 if (!target_bitrate.has_value())
1132 continue;
1133 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1134 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1135 bitrate_item.temporal_layer);
1136 auto time_series_it = time_series.find(layer);
1137 if (time_series_it == time_series.end()) {
1138 std::string layer_name = GetLayerName(layer);
1139 bool inserted;
1140 std::tie(time_series_it, inserted) = time_series.insert(
1141 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1142 RTC_DCHECK(inserted);
1143 }
1144 float x = config_.GetCallTimeSec(rtcp.log_time_us());
1145 float y = bitrate_item.target_bitrate_kbps;
1146 time_series_it->second.points.emplace_back(x, y);
1147 }
1148 }
1149 for (auto& layer : time_series) {
1150 plot->AppendTimeSeries(std::move(layer.second));
1151 }
1152 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1153 "Time (s)", kLeftMargin, kRightMargin);
1154 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1155 if (direction == kIncomingPacket)
1156 plot->SetTitle("Target bitrate per incoming layer");
1157 else
1158 plot->SetTitle("Target bitrate per outgoing layer");
1159}
1160
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001161void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1162 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1163 PointStyle::kHighlight);
1164 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1165 PointStyle::kHighlight);
1166 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1167 PointStyle::kHighlight);
1168 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1169 PointStyle::kHighlight);
1170
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001171 LogBasedNetworkControllerSimulation simulation(
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001172 std::make_unique<GoogCcNetworkControllerFactory>(),
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001173 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1174 if (update.target_rate) {
1175 target_rates.points.emplace_back(
1176 config_.GetCallTimeSec(at_time.us()),
1177 update.target_rate->target_rate.kbps<float>());
1178 }
1179 });
1180
1181 simulation.ProcessEventsInLog(parsed_log_);
1182 for (const auto& logged : parsed_log_.bwe_delay_updates())
1183 delay_based.points.emplace_back(
1184 config_.GetCallTimeSec(logged.log_time_us()),
1185 logged.bitrate_bps / 1000);
1186 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1187 probe_results.points.emplace_back(
1188 config_.GetCallTimeSec(logged.log_time_us()),
1189 logged.bitrate_bps / 1000);
1190 for (const auto& logged : parsed_log_.bwe_loss_updates())
1191 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time_us()),
1192 logged.bitrate_bps / 1000);
1193
1194 plot->AppendTimeSeries(std::move(delay_based));
1195 plot->AppendTimeSeries(std::move(loss_based));
1196 plot->AppendTimeSeries(std::move(probe_results));
1197 plot->AppendTimeSeries(std::move(target_rates));
1198
1199 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1200 "Time (s)", kLeftMargin, kRightMargin);
1201 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1202 plot->SetTitle("Simulated BWE behavior");
1203}
1204
Bjorn Terelius28db2662017-10-04 14:22:43 +02001205void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001206 using RtpPacketType = LoggedRtpPacketOutgoing;
1207 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001208
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001209 // TODO(terelius): This could be provided by the parser.
1210 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1211 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1212 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1213 outgoing_rtp.insert(
1214 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001215 }
1216
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001217 const std::vector<TransportFeedbackType>& incoming_rtcp =
1218 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001219
1220 SimulatedClock clock(0);
1221 BitrateObserver observer;
Danil Chapovalov83bbe912019-08-07 12:24:53 +02001222 RtcEventLogNull null_event_log;
nisse0245da02016-11-30 03:35:20 -08001223 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001224 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001225 TransportFeedbackAdapter transport_feedback;
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001226 auto factory = GoogCcNetworkControllerFactory();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001227 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001228 // TODO(holmer): Log the call config and use that here instead.
1229 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001230 NetworkControllerConfig cc_config;
Sebastian Jansson78416b62018-10-18 13:08:17 +02001231 cc_config.constraints.at_time = Timestamp::us(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001232 cc_config.constraints.starting_rate = DataRate::bps(kDefaultStartBitrateBps);
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001233 cc_config.event_log = &null_event_log;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001234 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001235
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001236 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1237 PointStyle::kHighlight);
1238 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1239 PointStyle::kHighlight);
1240 TimeSeries acked_estimate_time_series(
1241 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001242
1243 auto rtp_iterator = outgoing_rtp.begin();
1244 auto rtcp_iterator = incoming_rtcp.begin();
1245
1246 auto NextRtpTime = [&]() {
1247 if (rtp_iterator != outgoing_rtp.end())
1248 return static_cast<int64_t>(rtp_iterator->first);
1249 return std::numeric_limits<int64_t>::max();
1250 };
1251
1252 auto NextRtcpTime = [&]() {
1253 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001254 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001255 return std::numeric_limits<int64_t>::max();
1256 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001257 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001258
1259 auto NextProcessTime = [&]() {
1260 if (rtcp_iterator != incoming_rtcp.end() ||
1261 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001262 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001263 }
1264 return std::numeric_limits<int64_t>::max();
1265 };
1266
Stefan Holmer492ee282016-10-27 17:19:20 +02001267 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001268#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001269 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001270 // The event_log_visualizer should normally not be compiled with
1271 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
Mirko Bonadei604e75c2019-07-25 11:55:47 +02001272 // However, compiling with BWE_TEST_LOGGING, running with --plot_sendside_bwe
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001273 // and piping the output to plot_dynamics.py can be used as a hack to get the
1274 // internal state of various BWE components. In this case, it is important
1275 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
Sebastian Jansson4ad51d82019-06-11 11:24:40 +02001276 // GoogCcNetworkController since that would lead to duplicate outputs.
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001277 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Sebastian Jansson95edb032019-01-17 16:24:12 +01001278 &field_trial_config_,
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001279 std::make_unique<BitrateEstimator>(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001280#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001281 int64_t time_us =
1282 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001283 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001284 while (time_us != std::numeric_limits<int64_t>::max()) {
1285 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001286 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1287 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1288 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1289 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1290 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
Erik Språng30a276b2019-04-23 12:00:11 +02001291 RtpPacketSendInfo packet_info;
1292 packet_info.ssrc = rtp_packet.rtp.header.ssrc;
Bjorn Tereliusf2e9cab2019-05-27 16:44:09 +02001293 packet_info.transport_sequence_number =
Erik Språng30a276b2019-04-23 12:00:11 +02001294 rtp_packet.rtp.header.extension.transportSequenceNumber;
1295 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
1296 packet_info.has_rtp_sequence_number = true;
1297 packet_info.length = rtp_packet.rtp.total_length;
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001298 transport_feedback.AddPacket(
Erik Språng30a276b2019-04-23 12:00:11 +02001299 packet_info,
1300 0u, // Per packet overhead bytes.
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001301 Timestamp::us(rtp_packet.rtp.log_time_us()));
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001302 rtc::SentPacket sent_packet(
1303 rtp_packet.rtp.header.extension.transportSequenceNumber,
1304 rtp_packet.rtp.log_time_us() / 1000);
1305 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1306 if (sent_msg)
1307 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1308 }
1309 ++rtp_iterator;
1310 }
Stefan Holmer13181032016-07-29 14:48:54 +02001311 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001312 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001313
1314 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001315 rtcp_iterator->transport_feedback,
1316 Timestamp::ms(clock.TimeInMilliseconds()));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001317 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001318 if (feedback_msg) {
1319 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001320 std::vector<PacketResult> feedback =
1321 feedback_msg->SortedByReceiveTime();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001322 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001323#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001324 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001325#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001326 for (const PacketResult& packet : feedback)
1327 acked_bitrate.Update(packet.sent_packet.size.bytes(),
1328 packet.receive_time.ms());
1329 bitrate_bps = acked_bitrate.Rate(feedback.back().receive_time.ms());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001330 }
Stefan Holmer13181032016-07-29 14:48:54 +02001331 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001332
Bjorn Terelius068fc352019-02-13 22:38:25 +01001333 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001334 float y = bitrate_bps.value_or(0) / 1000;
1335 acked_time_series.points.emplace_back(x, y);
1336#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001337 y = acknowledged_bitrate_estimator.bitrate()
1338 .value_or(DataRate::Zero())
1339 .kbps();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001340 acked_estimate_time_series.points.emplace_back(x, y);
1341#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001342 ++rtcp_iterator;
1343 }
stefanc3de0332016-08-02 07:22:17 -07001344 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1345 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001346 ProcessInterval msg;
1347 msg.at_time = Timestamp::us(clock.TimeInMicroseconds());
1348 observer.Update(goog_cc->OnProcessInterval(msg));
1349 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001350 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001351 if (observer.GetAndResetBitrateUpdated() ||
1352 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001353 uint32_t y = observer.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001354 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001355 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001356 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001357 }
1358 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1359 }
1360 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001361 plot->AppendTimeSeries(std::move(time_series));
1362 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001363 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001364
Bjorn Terelius068fc352019-02-13 22:38:25 +01001365 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1366 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001367 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001368 plot->SetTitle("Simulated send-side BWE behavior");
1369}
1370
1371void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001372 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001373 class RembInterceptingPacketRouter : public PacketRouter {
1374 public:
1375 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1376 uint32_t bitrate_bps) override {
1377 last_bitrate_bps_ = bitrate_bps;
1378 bitrate_updated_ = true;
1379 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1380 }
1381 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1382 bool GetAndResetBitrateUpdated() {
1383 bool bitrate_updated = bitrate_updated_;
1384 bitrate_updated_ = false;
1385 return bitrate_updated;
1386 }
1387
1388 private:
1389 uint32_t last_bitrate_bps_;
1390 bool bitrate_updated_;
1391 };
1392
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001393 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001394
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001395 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1396 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1397 for (const auto& rtp_packet : stream.incoming_packets)
1398 incoming_rtp.insert(
1399 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001400 }
1401 }
1402
1403 SimulatedClock clock(0);
1404 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001405 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001406 // Is this intentional?
1407 ReceiveSideCongestionController rscc(&clock, &packet_router);
1408 // TODO(holmer): Log the call config and use that here instead.
1409 // static const uint32_t kDefaultStartBitrateBps = 300000;
1410 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1411
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001412 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1413 PointStyle::kHighlight);
1414 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001415
1416 RateStatistics acked_bitrate(250, 8000);
1417 int64_t last_update_us = 0;
1418 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001419 const RtpPacketType& packet = *kv.second;
1420 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1421 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1422 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001423 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001424 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001425 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001426 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001427 if (bitrate_bps) {
1428 uint32_t y = *bitrate_bps / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001429 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001430 acked_time_series.points.emplace_back(x, y);
1431 }
1432 if (packet_router.GetAndResetBitrateUpdated() ||
1433 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1434 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001435 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001436 time_series.points.emplace_back(x, y);
1437 last_update_us = clock.TimeInMicroseconds();
1438 }
1439 }
1440 // Add the data set to the plot.
1441 plot->AppendTimeSeries(std::move(time_series));
1442 plot->AppendTimeSeries(std::move(acked_time_series));
1443
Bjorn Terelius068fc352019-02-13 22:38:25 +01001444 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1445 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001446 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1447 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001448}
1449
tereliuse34c19c2016-08-15 08:47:14 -07001450void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001451 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001452 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001453 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1454 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001455
stefana0a8ed72017-09-06 02:06:32 -07001456 int64_t prev_y = 0;
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001457 std::vector<MatchedSendArrivalTimes> matched_rtp_rtcp =
1458 GetNetworkTrace(parsed_log_);
1459 absl::c_stable_sort(matched_rtp_rtcp, [](const MatchedSendArrivalTimes& a,
1460 const MatchedSendArrivalTimes& b) {
1461 return a.feedback_arrival_time_ms < b.feedback_arrival_time_ms;
1462 });
1463 for (const auto& packet : matched_rtp_rtcp) {
Sebastian Jansson74f96ec2019-10-29 12:57:54 +01001464 if (packet.arrival_time_ms == MatchedSendArrivalTimes::kNotReceived)
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001465 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001466 float x = config_.GetCallTimeSec(1000 * packet.feedback_arrival_time_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001467 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1468 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001469 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1470 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1471 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001472 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001473 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001474
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001475 // We assume that the base network delay (w/o queues) is equal to half
1476 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
Mirko Bonadei604e75c2019-07-25 11:55:47 +02001477 // observed 1-ways delay and add half the minimum RTT.
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001478 const int64_t estimated_clock_offset_ms =
1479 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001480 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001481 point.y -= estimated_clock_offset_ms;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001482
stefanc3de0332016-08-02 07:22:17 -07001483 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001484 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
stefanc3de0332016-08-02 07:22:17 -07001485
Bjorn Terelius068fc352019-02-13 22:38:25 +01001486 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1487 "Time (s)", kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001488 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +01001489 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001490}
stefan08383272016-12-20 08:51:52 -08001491
Bjorn Terelius0295a962017-10-25 17:42:41 +02001492void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001493 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1494 const std::vector<LoggedRtpPacketOutgoing>& packets =
1495 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001496
Konrad Hofbauerbfb735b2019-04-16 11:12:11 +02001497 if (IsRtxSsrc(kOutgoingPacket, stream.ssrc)) {
1498 continue;
1499 }
1500
Bjorn Terelius0295a962017-10-25 17:42:41 +02001501 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001502 RTC_LOG(LS_WARNING)
1503 << "Can't estimate a the RTP clock frequency or the "
1504 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001505 continue;
1506 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001507 int64_t end_time_us = log_segments_.empty()
1508 ? std::numeric_limits<int64_t>::max()
1509 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001510 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001511 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001512 if (!estimated_frequency)
1513 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001514 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1515 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001516 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001517 << "Video stream should use a 90 kHz clock but appears to use "
1518 << *estimated_frequency / 1000 << ". Discarding.";
1519 continue;
1520 }
1521
1522 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001523 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001524 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001525 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001526 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1527 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001528 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1529 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1530 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001531 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001532 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001533 first_capture_timestamp) /
1534 *estimated_frequency * 1000;
1535 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001536 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1537 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001538 float x = config_.GetCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001539 float y = send_time_ms - capture_time_ms;
1540 pacer_delay_series.points.emplace_back(x, y);
1541 }
1542 plot->AppendTimeSeries(std::move(pacer_delay_series));
1543 }
1544
Bjorn Terelius068fc352019-02-13 22:38:25 +01001545 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1546 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001547 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1548 plot->SetTitle(
1549 "Delay from capture to send time. (First packet normalized to 0.)");
1550}
1551
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001552void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1553 Plot* plot) {
1554 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1555 TimeSeries rtp_timestamps(
1556 GetStreamName(direction, stream.ssrc) + " capture-time",
1557 LineStyle::kLine, PointStyle::kHighlight);
1558 for (const auto& packet : stream.packet_view) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001559 float x = config_.GetCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001560 float y = packet.header.timestamp;
1561 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001562 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001563 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001564
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001565 TimeSeries rtcp_timestamps(
1566 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1567 LineStyle::kLine, PointStyle::kHighlight);
1568 // TODO(terelius): Why only sender reports?
1569 const auto& sender_reports = parsed_log_.sender_reports(direction);
1570 for (const auto& rtcp : sender_reports) {
1571 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1572 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001573 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001574 float y = rtcp.sr.rtp_timestamp();
1575 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001576 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001577 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001578 }
1579
Bjorn Terelius068fc352019-02-13 22:38:25 +01001580 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1581 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001582 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1583 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001584}
michaelt6e5b2192017-02-22 07:33:27 -08001585
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001586void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1587 PacketDirection direction,
1588 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1589 std::string title,
1590 std::string yaxis_label,
1591 Plot* plot) {
1592 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1593 const auto& sender_reports = parsed_log_.sender_reports(direction);
1594 for (const auto& rtcp : sender_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001595 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001596 uint32_t ssrc = rtcp.sr.sender_ssrc();
1597 for (const auto& block : rtcp.sr.report_blocks()) {
1598 float y = fy(block);
1599 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1600 bool inserted;
1601 if (sr_report_it == sr_reports_by_ssrc.end()) {
1602 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1603 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1604 LineStyle::kLine, PointStyle::kHighlight));
1605 }
1606 sr_report_it->second.points.emplace_back(x, y);
1607 }
1608 }
1609 for (auto& kv : sr_reports_by_ssrc) {
1610 plot->AppendTimeSeries(std::move(kv.second));
1611 }
1612
1613 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1614 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1615 for (const auto& rtcp : receiver_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001616 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001617 uint32_t ssrc = rtcp.rr.sender_ssrc();
1618 for (const auto& block : rtcp.rr.report_blocks()) {
1619 float y = fy(block);
1620 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1621 bool inserted;
1622 if (rr_report_it == rr_reports_by_ssrc.end()) {
1623 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1624 ssrc,
1625 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1626 LineStyle::kLine, PointStyle::kHighlight));
1627 }
1628 rr_report_it->second.points.emplace_back(x, y);
1629 }
1630 }
1631 for (auto& kv : rr_reports_by_ssrc) {
1632 plot->AppendTimeSeries(std::move(kv.second));
1633 }
1634
Bjorn Terelius068fc352019-02-13 22:38:25 +01001635 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1636 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001637 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1638 plot->SetTitle(title);
1639}
1640
michaelt6e5b2192017-02-22 07:33:27 -08001641void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001642 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1643 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001644 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001645 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001646 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001647 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001648 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001649 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001650 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001651 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001652 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001653 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001654 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001655 ToCallTime, GetAnaBitrateBps,
1656 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001657 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001658 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1659 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001660 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1661 plot->SetTitle("Reported audio encoder target bitrate");
1662}
1663
1664void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001665 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1666 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001667 auto GetAnaFrameLengthMs =
1668 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001669 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001670 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001671 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001672 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001673 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001674 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001675 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001676 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001677 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001678 ToCallTime, GetAnaFrameLengthMs,
1679 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001680 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001681 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1682 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001683 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1684 plot->SetTitle("Reported audio encoder frame length");
1685}
1686
terelius2ee076d2017-08-15 02:04:02 -07001687void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001688 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001689 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001690 auto GetAnaPacketLoss =
1691 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001692 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001693 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001694 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001695 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001696 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001697 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001698 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001699 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001700 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001701 ToCallTime, GetAnaPacketLoss,
1702 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001703 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001704 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1705 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001706 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1707 kTopMargin);
1708 plot->SetTitle("Reported audio encoder lost packets");
1709}
1710
1711void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001712 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1713 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001714 auto GetAnaFecEnabled =
1715 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001716 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001717 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001718 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001719 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001720 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001721 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001722 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001723 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001724 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001725 ToCallTime, GetAnaFecEnabled,
1726 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001727 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001728 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1729 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001730 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1731 plot->SetTitle("Reported audio encoder FEC");
1732}
1733
1734void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001735 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1736 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001737 auto GetAnaDtxEnabled =
1738 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001739 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001740 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001741 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001742 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001743 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001744 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001745 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001746 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001747 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001748 ToCallTime, GetAnaDtxEnabled,
1749 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001750 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001751 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1752 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001753 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1754 plot->SetTitle("Reported audio encoder DTX");
1755}
1756
1757void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001758 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1759 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001760 auto GetAnaNumChannels =
1761 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001762 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001763 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001764 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001765 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001766 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001767 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001768 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001769 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001770 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001771 ToCallTime, GetAnaNumChannels,
1772 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001773 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001774 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1775 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001776 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1777 kBottomMargin, kTopMargin);
1778 plot->SetTitle("Reported audio encoder number of channels");
1779}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001780
1781class NetEqStreamInput : public test::NetEqInput {
1782 public:
1783 // Does not take any ownership, and all pointers must refer to valid objects
1784 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001785 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001786 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001787 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001788 : packet_stream_(*packet_stream),
1789 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001790 output_events_it_(output_events->begin()),
1791 output_events_end_(output_events->end()),
1792 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001793 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001794 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001795 }
1796
Danil Chapovalov431abd92018-06-18 12:54:17 +02001797 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001798 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001799 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001800 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001801 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001802 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001803 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001804 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001805 }
1806
Danil Chapovalov431abd92018-06-18 12:54:17 +02001807 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001808 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001809 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001810 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001811 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001812 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001813 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001814 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001815 }
1816
1817 std::unique_ptr<PacketData> PopPacket() override {
1818 if (packet_stream_it_ == packet_stream_.end()) {
1819 return std::unique_ptr<PacketData>();
1820 }
1821 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001822 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001823 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001824
1825 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1826 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001827 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1828 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001829 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1830
1831 ++packet_stream_it_;
1832 return packet_data;
1833 }
1834
1835 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001836 if (output_events_it_ != output_events_end_) {
1837 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001838 }
1839 }
1840
1841 bool ended() const override { return !NextEventTime(); }
1842
Danil Chapovalov431abd92018-06-18 12:54:17 +02001843 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001844 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001845 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001846 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001847 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001848 }
1849
1850 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001851 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1852 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001853 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1854 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001855 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001856};
1857
1858namespace {
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001859
1860// Factory to create a "replacement decoder" that produces the decoded audio
1861// by reading from a file rather than from the encoded payloads.
1862class ReplacementAudioDecoderFactory : public AudioDecoderFactory {
1863 public:
1864 ReplacementAudioDecoderFactory(const absl::string_view replacement_file_name,
1865 int file_sample_rate_hz)
1866 : replacement_file_name_(replacement_file_name),
1867 file_sample_rate_hz_(file_sample_rate_hz) {}
1868
1869 std::vector<AudioCodecSpec> GetSupportedDecoders() override {
1870 RTC_NOTREACHED();
1871 return {};
1872 }
1873
1874 bool IsSupportedDecoder(const SdpAudioFormat& format) override {
1875 return true;
1876 }
1877
1878 std::unique_ptr<AudioDecoder> MakeAudioDecoder(
1879 const SdpAudioFormat& format,
1880 absl::optional<AudioCodecPairId> codec_pair_id) override {
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001881 auto replacement_file = std::make_unique<test::ResampleInputAudioFile>(
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001882 replacement_file_name_, file_sample_rate_hz_);
1883 replacement_file->set_output_rate_hz(48000);
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001884 return std::make_unique<test::FakeDecodeFromFile>(
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001885 std::move(replacement_file), 48000, false);
1886 }
1887
1888 private:
1889 const std::string replacement_file_name_;
1890 const int file_sample_rate_hz_;
1891};
1892
henrik.lundin3c938fc2017-06-14 06:09:58 -07001893// Creates a NetEq test object and all necessary input and output helpers. Runs
1894// the test and returns the NetEqDelayAnalyzer object that was used to
1895// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001896std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001897 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001898 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001899 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001900 const std::string& replacement_file_name,
1901 int file_sample_rate_hz) {
1902 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001903 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001904
1905 constexpr int kReplacementPt = 127;
1906 std::set<uint8_t> cn_types;
1907 std::set<uint8_t> forbidden_types;
1908 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1909 cn_types, forbidden_types));
1910
1911 NetEq::Config config;
1912 config.max_packets_in_buffer = 200;
1913 config.enable_fast_accelerate = true;
1914
1915 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1916
Niels Möller3f651d82018-12-19 15:06:17 +01001917 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001918 new rtc::RefCountedObject<ReplacementAudioDecoderFactory>(
1919 replacement_file_name, file_sample_rate_hz);
Niels Möller3f651d82018-12-19 15:06:17 +01001920
Niels Möller05543682019-01-10 16:55:06 +01001921 test::NetEqTest::DecoderMap codecs = {
1922 {kReplacementPt, SdpAudioFormat("l16", 48000, 1)}};
henrik.lundin3c938fc2017-06-14 06:09:58 -07001923
1924 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1925 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001926 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1927 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001928 test::DefaultNetEqTestErrorCallback error_cb;
1929 test::NetEqTest::Callbacks callbacks;
1930 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001931 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1932 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001933
Niels Möllerbd6dee82019-01-02 09:39:47 +01001934 test::NetEqTest test(config, decoder_factory, codecs, nullptr,
Niels Möller3f651d82018-12-19 15:06:17 +01001935 std::move(input), std::move(output), callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001936 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001937 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001938}
1939} // namespace
1940
Minyue Lic6ff7572018-05-04 09:46:44 +02001941EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001942 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001943 int file_sample_rate_hz) const {
1944 NetEqStatsGetterMap neteq_stats;
1945
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001946 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001947 const uint32_t ssrc = stream.ssrc;
1948 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1949 continue;
1950 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1951 &stream.incoming_packets;
1952 if (audio_packets == nullptr) {
1953 // No incoming audio stream found.
1954 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001955 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001956
Minyue Li27e2b7d2018-05-07 15:20:24 +02001957 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1958
1959 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1960 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1961 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1962 // Could not find output events with SSRC matching the input audio stream.
1963 // Using the first available stream of output events.
1964 output_events_it = parsed_log_.audio_playout_events().cbegin();
1965 }
1966
Danil Chapovalov431abd92018-06-18 12:54:17 +02001967 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001968 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001969 ? absl::nullopt
1970 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001971
1972 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1973 audio_packets, &output_events_it->second, end_time_ms,
1974 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001975 }
1976
Minyue Lic6ff7572018-05-04 09:46:44 +02001977 return neteq_stats;
1978}
1979
Minyue Lic97933f2018-08-10 12:51:15 +02001980// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1981// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001982void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001983 uint32_t ssrc,
1984 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001985 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001986 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1987 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1988 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1989 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1990
Minyue Li01d2a672018-06-21 21:17:19 +02001991 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001992 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1993 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001994
Minyue Lic97933f2018-08-10 12:51:15 +02001995 TimeSeries time_series_packet_arrival("packet arrival delay",
1996 LineStyle::kLine);
1997 TimeSeries time_series_relative_packet_arrival(
1998 "Relative packet arrival delay", LineStyle::kLine);
1999 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
2000 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
2001 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02002002
2003 for (const auto& data : arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002004 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002005 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002006 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002007 }
2008 for (const auto& data : corrected_arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002009 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002010 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002011 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02002012 TimeSeriesPoint(x, y));
2013 }
2014 for (const auto& data : playout_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002015 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002016 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002017 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002018 }
2019 for (const auto& data : target_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002020 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002021 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002022 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002023 }
2024
Minyue Lic97933f2018-08-10 12:51:15 +02002025 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
2026 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
2027 plot->AppendTimeSeries(std::move(time_series_play_time));
2028 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002029
Bjorn Terelius068fc352019-02-13 22:38:25 +01002030 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2031 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002032 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
2033 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002034 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
2035}
2036
Minyue Lic9ac93f2018-06-26 13:01:32 +02002037template <typename NetEqStatsType>
2038void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02002039 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02002040 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
2041 const test::NetEqStatsGetter*)> data_extractor,
2042 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02002043 const std::string& plot_name,
2044 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02002045 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02002046
2047 for (const auto& st : neteq_stats) {
2048 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02002049 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
2050 data_extractor(st.second.get());
2051 for (const auto& data : *data_vector) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002052 const float time =
2053 config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Lic9ac93f2018-06-26 13:01:32 +02002054 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002055 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02002056 }
2057 }
2058
2059 for (auto& series : time_series) {
2060 series.second.label = GetStreamName(kIncomingPacket, series.first);
2061 series.second.line_style = LineStyle::kLine;
2062 plot->AppendTimeSeries(std::move(series.second));
2063 }
2064
Bjorn Terelius068fc352019-02-13 22:38:25 +01002065 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2066 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002067 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002068 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002069}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002070
Minyue Lic9ac93f2018-06-26 13:01:32 +02002071void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
2072 const NetEqStatsGetterMap& neteq_stats,
2073 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
2074 const std::string& plot_name,
2075 Plot* plot) const {
2076 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
2077 neteq_stats,
2078 [](const test::NetEqStatsGetter* stats_getter) {
2079 return stats_getter->stats();
2080 },
2081 stats_extractor, plot_name, plot);
2082}
2083
2084void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
2085 const NetEqStatsGetterMap& neteq_stats,
2086 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
2087 const std::string& plot_name,
2088 Plot* plot) const {
2089 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
2090 neteq_stats,
2091 [](const test::NetEqStatsGetter* stats_getter) {
2092 return stats_getter->lifetime_stats();
2093 },
2094 stats_extractor, plot_name, plot);
2095}
2096
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002097void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
2098 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002099 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002100 if (configs_by_cp_id.find(config.candidate_pair_id) ==
2101 configs_by_cp_id.end()) {
2102 const std::string candidate_pair_desc =
2103 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08002104 configs_by_cp_id[config.candidate_pair_id] =
2105 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
2106 candidate_pair_desc,
2107 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002108 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2109 candidate_pair_desc;
2110 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002111 float x = config_.GetCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002112 float y = static_cast<float>(config.type);
2113 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
2114 }
2115
2116 // TODO(qingsi): There can be a large number of candidate pairs generated by
2117 // certain calls and the frontend cannot render the chart in this case due to
2118 // the failure of generating a palette with the same number of colors.
2119 for (auto& kv : configs_by_cp_id) {
2120 plot->AppendTimeSeries(std::move(kv.second));
2121 }
2122
Bjorn Terelius068fc352019-02-13 22:38:25 +01002123 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2124 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002125 plot->SetSuggestedYAxis(0, 3, "Config Type", kBottomMargin, kTopMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002126 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002127 plot->SetYAxisTickLabels(
2128 {{static_cast<float>(IceCandidatePairConfigType::kAdded), "ADDED"},
2129 {static_cast<float>(IceCandidatePairConfigType::kUpdated), "UPDATED"},
2130 {static_cast<float>(IceCandidatePairConfigType::kDestroyed),
2131 "DESTROYED"},
2132 {static_cast<float>(IceCandidatePairConfigType::kSelected),
2133 "SELECTED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002134}
2135
2136std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
2137 uint32_t candidate_pair_id) {
2138 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
2139 candidate_pair_desc_by_id_.end()) {
2140 return candidate_pair_desc_by_id_[candidate_pair_id];
2141 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002142 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002143 // TODO(qingsi): Add the handling of the "Updated" config event after the
2144 // visualization of property change for candidate pairs is introduced.
2145 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
2146 candidate_pair_desc_by_id_.end()) {
2147 const std::string candidate_pair_desc =
2148 GetCandidatePairLogDescriptionAsString(config);
2149 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2150 candidate_pair_desc;
2151 }
2152 }
2153 return candidate_pair_desc_by_id_[candidate_pair_id];
2154}
2155
2156void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002157 constexpr int kEventTypeOffset =
2158 static_cast<int>(IceCandidatePairConfigType::kNumValues);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002159 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002160 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002161 if (checks_by_cp_id.find(event.candidate_pair_id) ==
2162 checks_by_cp_id.end()) {
2163 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08002164 "[" + std::to_string(event.candidate_pair_id) + "]" +
2165 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002166 LineStyle::kNone, PointStyle::kHighlight);
2167 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002168 float x = config_.GetCallTimeSec(event.log_time_us());
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002169 float y = static_cast<float>(event.type) + kEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002170 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2171 }
2172
2173 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2174 for (auto& kv : checks_by_cp_id) {
2175 plot->AppendTimeSeries(std::move(kv.second));
2176 }
2177
Bjorn Terelius068fc352019-02-13 22:38:25 +01002178 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2179 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002180 plot->SetSuggestedYAxis(0, 4, "Connectivity State", kBottomMargin,
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002181 kTopMargin);
2182 plot->SetTitle("[IceEventLog] ICE connectivity checks");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002183
2184 plot->SetYAxisTickLabels(
2185 {{static_cast<float>(IceCandidatePairEventType::kCheckSent) +
2186 kEventTypeOffset,
2187 "CHECK SENT"},
2188 {static_cast<float>(IceCandidatePairEventType::kCheckReceived) +
2189 kEventTypeOffset,
2190 "CHECK RECEIVED"},
2191 {static_cast<float>(IceCandidatePairEventType::kCheckResponseSent) +
2192 kEventTypeOffset,
2193 "RESPONSE SENT"},
2194 {static_cast<float>(IceCandidatePairEventType::kCheckResponseReceived) +
2195 kEventTypeOffset,
2196 "RESPONSE RECEIVED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002197}
2198
Zach Stein10a58012018-12-07 12:26:28 -08002199void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
2200 TimeSeries states("DTLS Transport State", LineStyle::kNone,
2201 PointStyle::kHighlight);
2202 for (const auto& event : parsed_log_.dtls_transport_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002203 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002204 float y = static_cast<float>(event.dtls_transport_state);
2205 states.points.emplace_back(x, y);
2206 }
2207 plot->AppendTimeSeries(std::move(states));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002208 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2209 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002210 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002211 "Transport State", kBottomMargin, kTopMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002212 plot->SetTitle("DTLS Transport State");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002213 plot->SetYAxisTickLabels(
2214 {{static_cast<float>(DtlsTransportState::kNew), "NEW"},
2215 {static_cast<float>(DtlsTransportState::kConnecting), "CONNECTING"},
2216 {static_cast<float>(DtlsTransportState::kConnected), "CONNECTED"},
2217 {static_cast<float>(DtlsTransportState::kClosed), "CLOSED"},
2218 {static_cast<float>(DtlsTransportState::kFailed), "FAILED"}});
Zach Stein10a58012018-12-07 12:26:28 -08002219}
2220
2221void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2222 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2223 PointStyle::kHighlight);
2224 for (const auto& event : parsed_log_.dtls_writable_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002225 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002226 float y = static_cast<float>(event.writable);
2227 writable.points.emplace_back(x, y);
2228 }
2229 plot->AppendTimeSeries(std::move(writable));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002230 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2231 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002232 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2233 plot->SetTitle("DTLS Writable State");
2234}
2235
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002236void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002237 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002238 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2239 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2240 }
2241 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2242 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2243 }
2244 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2245 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2246 }
2247 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2248 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2249 }
2250 for (const auto& alert : incoming_seq_num_jumps_) {
2251 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2252 }
2253 for (const auto& alert : incoming_capture_time_jumps_) {
2254 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2255 }
2256 for (const auto& alert : outgoing_seq_num_jumps_) {
2257 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2258 }
2259 for (const auto& alert : outgoing_capture_time_jumps_) {
2260 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2261 }
2262 for (const auto& alert : outgoing_high_loss_alerts_) {
2263 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002264 }
2265 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2266}
2267
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002268void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2269 // With 100 packets/s (~800kbps), false positives would require 10 s without
2270 // data.
2271 constexpr int64_t kMaxSeqNumJump = 1000;
2272 // With a 90 kHz clock, false positives would require 10 s without data.
2273 constexpr int64_t kMaxCaptureTimeJump = 900000;
2274
2275 int64_t end_time_us = log_segments_.empty()
2276 ? std::numeric_limits<int64_t>::max()
2277 : log_segments_.front().second;
2278
2279 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002280 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002281 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002282 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002283 // Check for gaps in sequence numbers and capture timestamps.
2284 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2285 for (const auto& packet : stream.packet_view) {
2286 if (packet.log_time_us() > end_time_us) {
2287 // Only process the first (LOG_START, LOG_END) segment.
2288 break;
2289 }
2290
2291 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2292 if (last_seq_num.has_value() &&
2293 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002294 Alert_SeqNumJump(direction,
2295 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002296 packet.header.ssrc);
2297 }
2298 last_seq_num.emplace(seq_num);
2299
2300 int64_t capture_time =
2301 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2302 if (last_capture_time.has_value() &&
2303 std::abs(capture_time - last_capture_time.value()) >
2304 kMaxCaptureTimeJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002305 Alert_CaptureTimeJump(direction,
2306 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002307 packet.header.ssrc);
2308 }
2309 last_capture_time.emplace(capture_time);
2310 }
2311 }
2312}
2313
2314void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2315 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2316 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2317 int64_t end_time_us = log_segments_.empty()
2318 ? std::numeric_limits<int64_t>::max()
2319 : log_segments_.front().second;
2320
2321 // TODO(terelius): The parser could provide a list of all packets, ordered
2322 // by time, for each direction.
2323 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2324 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2325 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2326 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2327 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002328 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002329 for (const auto& kv : rtp_in_direction) {
2330 int64_t timestamp = kv.first;
2331 if (timestamp > end_time_us) {
2332 // Only process the first (LOG_START, LOG_END) segment.
2333 break;
2334 }
2335 int64_t duration = timestamp - last_rtp_time.value_or(0);
2336 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2337 // No packet sent/received for more than 500 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002338 Alert_RtpLogTimeGap(direction, config_.GetCallTimeSec(timestamp),
2339 duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002340 }
2341 last_rtp_time.emplace(timestamp);
2342 }
2343
Danil Chapovalov431abd92018-06-18 12:54:17 +02002344 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002345 if (direction == kIncomingPacket) {
2346 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2347 if (rtcp.log_time_us() > end_time_us) {
2348 // Only process the first (LOG_START, LOG_END) segment.
2349 break;
2350 }
2351 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2352 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2353 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002354 Alert_RtcpLogTimeGap(direction,
2355 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002356 duration / 1000);
2357 }
2358 last_rtcp_time.emplace(rtcp.log_time_us());
2359 }
2360 } else {
2361 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2362 if (rtcp.log_time_us() > end_time_us) {
2363 // Only process the first (LOG_START, LOG_END) segment.
2364 break;
2365 }
2366 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2367 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2368 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002369 Alert_RtcpLogTimeGap(direction,
2370 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002371 duration / 1000);
2372 }
2373 last_rtcp_time.emplace(rtcp.log_time_us());
2374 }
2375 }
2376}
2377
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002378// TODO(terelius): Notifications could possibly be generated by the same code
2379// that produces the graphs. There is some code duplication that could be
2380// avoided, but that might be solved anyway when we move functionality from the
2381// analyzer to the parser.
2382void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002383 CreateStreamGapAlerts(kIncomingPacket);
2384 CreateStreamGapAlerts(kOutgoingPacket);
2385 CreateTransmissionGapAlerts(kIncomingPacket);
2386 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002387
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002388 int64_t end_time_us = log_segments_.empty()
2389 ? std::numeric_limits<int64_t>::max()
2390 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002391
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002392 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002393 // Loss feedback
2394 int64_t total_lost_packets = 0;
2395 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002396 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2397 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002398 // Only process the first (LOG_START, LOG_END) segment.
2399 break;
2400 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002401 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002402 bwe_update.expected_packets;
2403 total_lost_packets += lost_packets;
2404 total_expected_packets += bwe_update.expected_packets;
2405 }
2406 double avg_outgoing_loss =
2407 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002408 if (avg_outgoing_loss > kMaxLossFraction) {
2409 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002410 }
2411}
2412
terelius54ce6802016-07-13 06:44:41 -07002413} // namespace webrtc