blob: 9fcb510adcbc9ecc8c5fc66e7f4d44af98a9d7f5 [file] [log] [blame]
terelius54ce6802016-07-13 06:44:41 -07001/*
2 * Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
Mirko Bonadei575998c2019-07-25 13:57:41 +020011#include "rtc_tools/rtc_event_log_visualizer/analyzer.h"
terelius54ce6802016-07-13 06:44:41 -070012
13#include <algorithm>
Oleh Prypin6581f212017-11-16 00:17:05 +010014#include <cmath>
terelius54ce6802016-07-13 06:44:41 -070015#include <limits>
16#include <map>
Mirko Bonadei317a1f02019-09-17 17:06:18 +020017#include <memory>
terelius54ce6802016-07-13 06:44:41 -070018#include <string>
19#include <utility>
20
Björn Tereliusc69c1bb2019-10-11 15:06:58 +020021#include "absl/algorithm/container.h"
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +010022#include "absl/strings/string_view.h"
Artem Titov741daaf2019-03-21 14:37:36 +010023#include "api/function_view.h"
Sebastian Jansson95edb032019-01-17 16:24:12 +010024#include "api/transport/field_trial_based_config.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020025#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020026#include "call/audio_receive_stream.h"
27#include "call/audio_send_stream.h"
28#include "call/call.h"
29#include "call/video_receive_stream.h"
30#include "call/video_send_stream.h"
Kristoffer Erlandssona2ce4232020-04-01 14:33:30 +020031#include "logging/rtc_event_log/rtc_event_processor.h"
Elad Alon99a81b62017-09-21 10:25:29 +020032#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020033#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020034#include "modules/audio_coding/neteq/tools/audio_sink.h"
35#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
36#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
37#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
38#include "modules/audio_coding/neteq/tools/neteq_test.h"
39#include "modules/audio_coding/neteq/tools/resample_input_audio_file.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020040#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
41#include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020042#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020043#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020044#include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
Erik Språnge7942432019-06-12 13:30:02 +020045#include "modules/pacing/paced_sender.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010046#include "modules/pacing/packet_router.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020047#include "modules/remote_bitrate_estimator/include/bwe_defines.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020048#include "modules/rtp_rtcp/include/rtp_rtcp.h"
49#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020050#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020051#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
52#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
53#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
54#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
55#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
56#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
57#include "modules/rtp_rtcp/source/rtp_utility.h"
58#include "rtc_base/checks.h"
59#include "rtc_base/format_macros.h"
60#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020061#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020062#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020063#include "rtc_base/strings/string_builder.h"
Mirko Bonadei575998c2019-07-25 13:57:41 +020064#include "rtc_tools/rtc_event_log_visualizer/log_simulation.h"
terelius54ce6802016-07-13 06:44:41 -070065
Bjorn Terelius6984ad22017-10-24 12:19:45 +020066#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
67#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
68#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
69
tereliusdc35dcd2016-08-01 12:03:27 -070070namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070071
terelius54ce6802016-07-13 06:44:41 -070072namespace {
73
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080074const int kNumMicrosecsPerSec = 1000000;
75
terelius54ce6802016-07-13 06:44:41 -070076std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020077 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070078 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020079 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070080}
81
82// Checks whether an SSRC is contained in the list of desired SSRCs.
83// Note that an empty SSRC list matches every SSRC.
84bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
Mirko Bonadei1f173152019-07-25 15:28:14 +020085 if (desired_ssrc.empty())
terelius54ce6802016-07-13 06:44:41 -070086 return true;
87 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
88 desired_ssrc.end();
89}
90
91double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
92 // The timestamp is a fixed point representation with 6 bits for seconds
93 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080094 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
95 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070096 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080097 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -070098 return abs_send_time * kTimestampToMicroSec;
99}
100
101// Computes the difference |later| - |earlier| where |later| and |earlier|
102// are counters that wrap at |modulus|. The difference is chosen to have the
103// least absolute value. For example if |modulus| is 8, then the difference will
104// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
105// be in [-4, 4].
106int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
107 RTC_DCHECK_LE(1, modulus);
108 RTC_DCHECK_LT(later, modulus);
109 RTC_DCHECK_LT(earlier, modulus);
110 int64_t difference =
111 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
112 int64_t max_difference = modulus / 2;
113 int64_t min_difference = max_difference - modulus + 1;
114 if (difference > max_difference) {
115 difference -= modulus;
116 }
117 if (difference < min_difference) {
118 difference += modulus;
119 }
terelius6addf492016-08-23 17:34:07 -0700120 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100121 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
122 << " expected to be in the range ("
123 << min_difference / 2 << "," << max_difference / 2
124 << ") but is " << difference
125 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700126 }
terelius54ce6802016-07-13 06:44:41 -0700127 return difference;
128}
129
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200130// This is much more reliable for outgoing streams than for incoming streams.
131template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200132absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200133 const RtpPacketContainer& packets,
134 int64_t end_time_us) {
135 RTC_CHECK(packets.size() >= 2);
136 SeqNumUnwrapper<uint32_t> unwrapper;
Philip Eliasson1f850a62019-03-19 12:15:00 +0000137 int64_t first_rtp_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200138 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
139 int64_t first_log_timestamp = packets[0].log_time_us();
Philip Eliasson1f850a62019-03-19 12:15:00 +0000140 int64_t last_rtp_timestamp = first_rtp_timestamp;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200141 int64_t last_log_timestamp = first_log_timestamp;
142 for (size_t i = 1; i < packets.size(); i++) {
143 if (packets[i].log_time_us() > end_time_us)
144 break;
145 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
146 last_log_timestamp = packets[i].log_time_us();
147 }
148 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
149 RTC_LOG(LS_WARNING)
150 << "Failed to estimate RTP clock frequency: Stream too short. ("
151 << packets.size() << " packets, "
152 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200153 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200154 }
155 double duration =
156 static_cast<double>(last_log_timestamp - first_log_timestamp) /
157 kNumMicrosecsPerSec;
158 double estimated_frequency =
159 (last_rtp_timestamp - first_rtp_timestamp) / duration;
160 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
philipel3fa49382019-08-20 15:59:57 +0200161 if (std::fabs(estimated_frequency - f) < 0.15 * f) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200162 return f;
163 }
164 }
165 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
166 << estimated_frequency
philipel3fa49382019-08-20 15:59:57 +0200167 << " not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200168 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700169}
170
tereliusdc35dcd2016-08-01 12:03:27 -0700171constexpr float kLeftMargin = 0.01f;
172constexpr float kRightMargin = 0.02f;
173constexpr float kBottomMargin = 0.02f;
174constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700175
Danil Chapovalov431abd92018-06-18 12:54:17 +0200176absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100177 const LoggedRtpPacketIncoming& old_packet,
178 const LoggedRtpPacketIncoming& new_packet) {
179 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
180 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700181 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100182 new_packet.rtp.header.extension.absoluteSendTime,
183 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200184 int64_t recv_time_diff =
185 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700186 double delay_change_us =
187 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100188 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700189 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200190 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700191 }
192}
193
Danil Chapovalov431abd92018-06-18 12:54:17 +0200194absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100195 const LoggedRtpPacketIncoming& old_packet,
196 const LoggedRtpPacketIncoming& new_packet,
197 const double sample_rate) {
198 int64_t send_time_diff =
199 WrappingDifference(new_packet.rtp.header.timestamp,
200 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200201 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700202
terelius53dc23c2017-03-13 05:24:05 -0700203 double delay_change =
204 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100205 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700206 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100207 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100208 RTC_LOG(LS_WARNING) << "Old capture time "
209 << old_packet.rtp.header.timestamp << ", received time "
210 << old_packet.log_time_us();
211 RTC_LOG(LS_WARNING) << "New capture time "
212 << new_packet.rtp.header.timestamp << ", received time "
213 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100214 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800215 << static_cast<double>(recv_time_diff) /
216 kNumMicrosecsPerSec
217 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100218 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100219 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100220 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700221 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100222 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700223}
224
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200225// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700226// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200227template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200228void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200229 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200230 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200231 TimeSeries* result) {
232 for (size_t i = 0; i < data_view.size(); i++) {
233 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200234 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200235 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700236 if (y)
237 result->points.emplace_back(x, *y);
238 }
239}
240
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200241// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700242// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
243// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200244template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700245void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200246 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200247 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
248 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200249 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700250 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700251 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200252 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200253 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700254 if (y)
255 result->points.emplace_back(x, static_cast<float>(*y));
256 }
257}
258
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200259// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700260// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
261// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200262template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700263void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200264 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200265 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
266 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200267 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700268 TimeSeries* result) {
269 ResultType sum = 0;
270 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200271 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200272 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100273 if (y) {
terelius53dc23c2017-03-13 05:24:05 -0700274 sum += *y;
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100275 result->points.emplace_back(x, static_cast<float>(sum));
276 }
tereliusccbbf8d2016-08-10 07:34:28 -0700277 }
278}
279
terelius6addf492016-08-23 17:34:07 -0700280// Calculates a moving average of |data| and stores the result in a TimeSeries.
281// A data point is generated every |step| microseconds from |begin_time|
282// to |end_time|. The value of each data point is the average of the data
Mirko Bonadei604e75c2019-07-25 11:55:47 +0200283// during the preceding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200284template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700285void MovingAverage(
Danil Chapovalov431abd92018-06-18 12:54:17 +0200286 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200287 const IterableType& data_view,
Bjorn Terelius068fc352019-02-13 22:38:25 +0100288 AnalyzerConfig config,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200289 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700290 size_t window_index_begin = 0;
291 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700292 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700293
Bjorn Terelius068fc352019-02-13 22:38:25 +0100294 for (int64_t t = config.begin_time_; t < config.end_time_ + config.step_;
295 t += config.step_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200296 while (window_index_end < data_view.size() &&
297 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200298 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700299 if (value)
300 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700301 ++window_index_end;
302 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200303 while (window_index_begin < data_view.size() &&
304 data_view[window_index_begin].log_time_us() <
Bjorn Terelius068fc352019-02-13 22:38:25 +0100305 t - config.window_duration_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200306 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700307 if (value)
308 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700309 ++window_index_begin;
310 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800311 float window_duration_s =
Bjorn Terelius068fc352019-02-13 22:38:25 +0100312 static_cast<float>(config.window_duration_) / kNumMicrosecsPerSec;
313 float x = config.GetCallTimeSec(t);
terelius53dc23c2017-03-13 05:24:05 -0700314 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700315 result->points.emplace_back(x, y);
316 }
317}
318
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100319template <typename T>
320TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
321 AnalyzerConfig config,
322 std::string rtcp_name,
323 int category_id) {
324 TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
325 for (const auto& rtcp : rtcp_list) {
326 float x = config.GetCallTimeSec(rtcp.log_time_us());
327 float y = category_id;
328 time_series.points.emplace_back(x, y);
329 }
330 return time_series;
331}
332
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800333const char kUnknownEnumValue[] = "unknown";
334
335const char kIceCandidateTypeLocal[] = "local";
336const char kIceCandidateTypeStun[] = "stun";
337const char kIceCandidateTypePrflx[] = "prflx";
338const char kIceCandidateTypeRelay[] = "relay";
339
340const char kProtocolUdp[] = "udp";
341const char kProtocolTcp[] = "tcp";
342const char kProtocolSsltcp[] = "ssltcp";
343const char kProtocolTls[] = "tls";
344
345const char kAddressFamilyIpv4[] = "ipv4";
346const char kAddressFamilyIpv6[] = "ipv6";
347
348const char kNetworkTypeEthernet[] = "ethernet";
349const char kNetworkTypeLoopback[] = "loopback";
350const char kNetworkTypeWifi[] = "wifi";
351const char kNetworkTypeVpn[] = "vpn";
352const char kNetworkTypeCellular[] = "cellular";
353
354std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
355 switch (type) {
356 case webrtc::IceCandidateType::kLocal:
357 return kIceCandidateTypeLocal;
358 case webrtc::IceCandidateType::kStun:
359 return kIceCandidateTypeStun;
360 case webrtc::IceCandidateType::kPrflx:
361 return kIceCandidateTypePrflx;
362 case webrtc::IceCandidateType::kRelay:
363 return kIceCandidateTypeRelay;
364 default:
365 return kUnknownEnumValue;
366 }
367}
368
369std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
370 switch (protocol) {
371 case webrtc::IceCandidatePairProtocol::kUdp:
372 return kProtocolUdp;
373 case webrtc::IceCandidatePairProtocol::kTcp:
374 return kProtocolTcp;
375 case webrtc::IceCandidatePairProtocol::kSsltcp:
376 return kProtocolSsltcp;
377 case webrtc::IceCandidatePairProtocol::kTls:
378 return kProtocolTls;
379 default:
380 return kUnknownEnumValue;
381 }
382}
383
384std::string GetAddressFamilyAsString(
385 webrtc::IceCandidatePairAddressFamily family) {
386 switch (family) {
387 case webrtc::IceCandidatePairAddressFamily::kIpv4:
388 return kAddressFamilyIpv4;
389 case webrtc::IceCandidatePairAddressFamily::kIpv6:
390 return kAddressFamilyIpv6;
391 default:
392 return kUnknownEnumValue;
393 }
394}
395
396std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
397 switch (type) {
398 case webrtc::IceCandidateNetworkType::kEthernet:
399 return kNetworkTypeEthernet;
400 case webrtc::IceCandidateNetworkType::kLoopback:
401 return kNetworkTypeLoopback;
402 case webrtc::IceCandidateNetworkType::kWifi:
403 return kNetworkTypeWifi;
404 case webrtc::IceCandidateNetworkType::kVpn:
405 return kNetworkTypeVpn;
406 case webrtc::IceCandidateNetworkType::kCellular:
407 return kNetworkTypeCellular;
408 default:
409 return kUnknownEnumValue;
410 }
411}
412
413std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200414 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800415 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
416 // represents a pair of a local server-reflexive candidate on a WiFi network
417 // and a remote relay candidate using TCP as the relay protocol on a cell
418 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200419 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800420 std::string local_candidate_type =
421 GetIceCandidateTypeAsString(config.local_candidate_type);
422 std::string remote_candidate_type =
423 GetIceCandidateTypeAsString(config.remote_candidate_type);
424 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
425 local_candidate_type +=
426 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
427 }
428 ss << local_candidate_type << ":"
429 << GetNetworkTypeAsString(config.local_network_type) << ":"
430 << GetAddressFamilyAsString(config.local_address_family) << "->"
431 << remote_candidate_type << ":"
432 << GetAddressFamilyAsString(config.remote_address_family) << "@"
433 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200434 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800435}
436
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200437std::string GetDirectionAsString(PacketDirection direction) {
438 if (direction == kIncomingPacket) {
439 return "Incoming";
440 } else {
441 return "Outgoing";
442 }
443}
444
445std::string GetDirectionAsShortString(PacketDirection direction) {
446 if (direction == kIncomingPacket) {
447 return "In";
448 } else {
449 return "Out";
450 }
451}
452
terelius54ce6802016-07-13 06:44:41 -0700453} // namespace
454
Sebastian Janssonb290a6d2019-01-03 14:46:23 +0100455EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200456 bool normalize_time)
Bjorn Terelius068fc352019-02-13 22:38:25 +0100457 : parsed_log_(log) {
458 config_.window_duration_ = 250000;
459 config_.step_ = 10000;
460 config_.normalize_time_ = normalize_time;
461 config_.begin_time_ = parsed_log_.first_timestamp();
462 config_.end_time_ = parsed_log_.last_timestamp();
463 if (config_.end_time_ < config_.begin_time_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200464 RTC_LOG(LS_WARNING) << "No useful events in the log.";
Bjorn Terelius068fc352019-02-13 22:38:25 +0100465 config_.begin_time_ = config_.end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000466 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200467
468 const auto& log_start_events = parsed_log_.start_log_events();
469 const auto& log_end_events = parsed_log_.stop_log_events();
470 auto start_iter = log_start_events.begin();
471 auto end_iter = log_end_events.begin();
472 while (start_iter != log_start_events.end()) {
473 int64_t start = start_iter->log_time_us();
474 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200475 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200476 if (start_iter != log_start_events.end())
477 next_start.emplace(start_iter->log_time_us());
478 if (end_iter != log_end_events.end() &&
479 end_iter->log_time_us() <=
480 next_start.value_or(std::numeric_limits<int64_t>::max())) {
481 int64_t end = end_iter->log_time_us();
482 RTC_DCHECK_LE(start, end);
483 log_segments_.push_back(std::make_pair(start, end));
484 ++end_iter;
485 } else {
486 // we're missing an end event. Assume that it occurred just before the
487 // next start.
488 log_segments_.push_back(
Bjorn Terelius068fc352019-02-13 22:38:25 +0100489 std::make_pair(start, next_start.value_or(config_.end_time_)));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200490 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700491 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100492 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200493 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700494}
495
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200496class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200497 public:
498 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
499
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200500 void Update(NetworkControlUpdate update) {
501 if (update.target_rate) {
502 last_bitrate_bps_ = update.target_rate->target_rate.bps();
503 bitrate_updated_ = true;
504 }
Stefan Holmer13181032016-07-29 14:48:54 +0200505 }
506
507 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
508 uint32_t bitrate) override {}
509
510 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
511 bool GetAndResetBitrateUpdated() {
512 bool bitrate_updated = bitrate_updated_;
513 bitrate_updated_ = false;
514 return bitrate_updated;
515 }
516
517 private:
518 uint32_t last_bitrate_bps_;
519 bool bitrate_updated_;
520};
521
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200522void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700523 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200524 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
525 // Filter on SSRC.
526 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700527 continue;
terelius54ce6802016-07-13 06:44:41 -0700528 }
terelius54ce6802016-07-13 06:44:41 -0700529
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200530 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
531 LineStyle::kBar);
532 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200533 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200534 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200535 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100536 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200537 };
538 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
539 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700540 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700541 }
542
Bjorn Terelius068fc352019-02-13 22:38:25 +0100543 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
544 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700545 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
546 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200547 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700548}
549
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100550void EventLogAnalyzer::CreateRtcpTypeGraph(PacketDirection direction,
551 Plot* plot) {
552 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
553 parsed_log_.transport_feedbacks(direction), config_, "TWCC", 1));
554 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
555 parsed_log_.receiver_reports(direction), config_, "RR", 2));
556 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
557 parsed_log_.sender_reports(direction), config_, "SR", 3));
558 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
559 parsed_log_.extended_reports(direction), config_, "XR", 4));
560 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.nacks(direction),
561 config_, "NACK", 5));
562 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.rembs(direction),
563 config_, "REMB", 6));
564 plot->AppendTimeSeries(
565 CreateRtcpTypeTimeSeries(parsed_log_.firs(direction), config_, "FIR", 7));
566 plot->AppendTimeSeries(
567 CreateRtcpTypeTimeSeries(parsed_log_.plis(direction), config_, "PLI", 8));
568 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
569 "Time (s)", kLeftMargin, kRightMargin);
570 plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
571 plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
Bjorn Tereliusf640b872019-07-24 15:46:39 +0200572 plot->SetYAxisTickLabels({{1, "TWCC"},
573 {2, "RR"},
574 {3, "SR"},
575 {4, "XR"},
576 {5, "NACK"},
577 {6, "REMB"},
578 {7, "FIR"},
579 {8, "PLI"}});
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100580}
581
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200582template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700583void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700584 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200585 const IterableType& packets,
586 const std::string& label) {
587 TimeSeries time_series(label, LineStyle::kStep);
588 for (size_t i = 0; i < packets.size(); i++) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100589 float x = config_.GetCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200590 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700591 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200592 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700593}
594
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200595void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
596 Plot* plot) {
597 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
598 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
599 continue;
600 std::string label =
601 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
602 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
603 }
604 std::string label =
605 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
606 if (direction == kIncomingPacket) {
607 CreateAccumulatedPacketsTimeSeries(
608 plot, parsed_log_.incoming_rtcp_packets(), label);
609 } else {
610 CreateAccumulatedPacketsTimeSeries(
611 plot, parsed_log_.outgoing_rtcp_packets(), label);
612 }
philipelccd74892016-09-05 02:46:25 -0700613
Bjorn Terelius068fc352019-02-13 22:38:25 +0100614 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
615 "Time (s)", kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700616 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200617 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
618 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700619}
620
Kristoffer Erlandsson283c1062020-03-30 13:01:37 +0200621void EventLogAnalyzer::CreatePacketRateGraph(PacketDirection direction,
622 Plot* plot) {
623 auto CountPackets = [](auto packet) { return 1.0; };
624 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
625 // Filter on SSRC.
626 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
627 continue;
628 }
629 TimeSeries time_series(
630 std::string("RTP ") + GetStreamName(direction, stream.ssrc),
631 LineStyle::kLine);
632 MovingAverage<LoggedRtpPacket, double>(CountPackets, stream.packet_view,
633 config_, &time_series);
634 plot->AppendTimeSeries(std::move(time_series));
635 }
636 TimeSeries time_series(
637 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")",
638 LineStyle::kLine);
639 if (direction == kIncomingPacket) {
640 MovingAverage<LoggedRtcpPacketIncoming, double>(
641 CountPackets, parsed_log_.incoming_rtcp_packets(), config_,
642 &time_series);
643 } else {
644 MovingAverage<LoggedRtcpPacketOutgoing, double>(
645 CountPackets, parsed_log_.outgoing_rtcp_packets(), config_,
646 &time_series);
647 }
648 plot->AppendTimeSeries(std::move(time_series));
649
650 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
651 "Time (s)", kLeftMargin, kRightMargin);
652 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
653 kTopMargin);
654 plot->SetTitle("Rate of " + GetDirectionAsString(direction) +
655 " RTP/RTCP packets");
656}
657
Kristoffer Erlandssona2ce4232020-04-01 14:33:30 +0200658void EventLogAnalyzer::CreateTotalPacketRateGraph(PacketDirection direction,
659 Plot* plot) {
660 // Contains a log timestamp to enable counting logged events of different
661 // types using MovingAverage().
662 class LogTime {
663 public:
664 explicit LogTime(int64_t log_time_us) : log_time_us_(log_time_us) {}
665
666 int64_t log_time_us() const { return log_time_us_; }
667
668 private:
669 int64_t log_time_us_;
670 };
671
672 std::vector<LogTime> packet_times;
673 auto handle_rtp = [&](const LoggedRtpPacket& packet) {
674 packet_times.emplace_back(packet.log_time_us());
675 };
676 RtcEventProcessor process;
677 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
678 process.AddEvents(stream.packet_view, handle_rtp);
679 }
680 if (direction == kIncomingPacket) {
681 auto handle_incoming_rtcp = [&](const LoggedRtcpPacketIncoming& packet) {
682 packet_times.emplace_back(packet.log_time_us());
683 };
684 process.AddEvents(parsed_log_.incoming_rtcp_packets(),
685 handle_incoming_rtcp);
686 } else {
687 auto handle_outgoing_rtcp = [&](const LoggedRtcpPacketOutgoing& packet) {
688 packet_times.emplace_back(packet.log_time_us());
689 };
690 process.AddEvents(parsed_log_.outgoing_rtcp_packets(),
691 handle_outgoing_rtcp);
692 }
693 process.ProcessEventsInOrder();
694 TimeSeries time_series(std::string("Total ") + "(" +
695 GetDirectionAsShortString(direction) + ") packets",
696 LineStyle::kLine);
697 MovingAverage<LogTime, uint64_t>([](auto packet) { return 1; }, packet_times,
698 config_, &time_series);
699 plot->AppendTimeSeries(std::move(time_series));
700
701 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
702 "Time (s)", kLeftMargin, kRightMargin);
703 plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
704 kTopMargin);
705 plot->SetTitle("Rate of all " + GetDirectionAsString(direction) +
706 " RTP/RTCP packets");
707}
708
terelius54ce6802016-07-13 06:44:41 -0700709// For each SSRC, plot the time between the consecutive playouts.
710void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200711 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
712 uint32_t ssrc = playout_stream.first;
713 if (!MatchingSsrc(ssrc, desired_ssrc_))
714 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200715 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200716 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200717 for (const auto& playout_event : playout_stream.second) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100718 float x = config_.GetCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200719 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200720 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200721 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200722 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200723 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700724 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200725 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700726 }
727
Bjorn Terelius068fc352019-02-13 22:38:25 +0100728 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
729 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700730 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
731 kTopMargin);
732 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700733}
734
ivocaac9d6f2016-09-22 07:01:47 -0700735// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200736void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
737 Plot* plot) {
738 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
739 if (!IsAudioSsrc(direction, stream.ssrc))
740 continue;
741 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
742 LineStyle::kLine);
743 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700744 if (packet.header.extension.hasAudioLevel) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100745 float x = config_.GetCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700746 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
747 // Here we convert it to dBov.
748 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200749 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700750 }
751 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200752 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700753 }
754
Bjorn Terelius068fc352019-02-13 22:38:25 +0100755 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
756 "Time (s)", kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200757 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200758 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700759}
760
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100761// For each SSRC, plot the sequence number difference between consecutive
762// incoming packets.
terelius54ce6802016-07-13 06:44:41 -0700763void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200764 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
765 // Filter on SSRC.
766 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700767 continue;
terelius54ce6802016-07-13 06:44:41 -0700768 }
terelius54ce6802016-07-13 06:44:41 -0700769
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200770 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
771 LineStyle::kBar);
772 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
773 const LoggedRtpPacketIncoming& new_packet) {
774 int64_t diff =
775 WrappingDifference(new_packet.rtp.header.sequenceNumber,
776 old_packet.rtp.header.sequenceNumber, 1ul << 16);
777 return diff;
778 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200779 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100780 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200781 };
782 ProcessPairs<LoggedRtpPacketIncoming, float>(
783 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
784 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700785 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700786 }
787
Bjorn Terelius068fc352019-02-13 22:38:25 +0100788 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
789 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700790 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
791 kTopMargin);
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100792 plot->SetTitle("Incoming sequence number delta");
terelius54ce6802016-07-13 06:44:41 -0700793}
794
Stefan Holmer99f8e082016-09-09 13:37:50 +0200795void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200796 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
797 const std::vector<LoggedRtpPacketIncoming>& packets =
798 stream.incoming_packets;
799 // Filter on SSRC.
Mirko Bonadei1f173152019-07-25 15:28:14 +0200800 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.empty()) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200801 continue;
802 }
803
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200804 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
805 LineStyle::kLine, PointStyle::kHighlight);
806 // TODO(terelius): Should the window and step size be read from the class
807 // instead?
808 const int64_t kWindowUs = 1000000;
809 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100810 SeqNumUnwrapper<uint16_t> unwrapper_;
811 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800812 size_t window_index_begin = 0;
813 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200814 uint64_t highest_seq_number =
815 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
816 uint64_t highest_prior_seq_number =
817 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800818
Bjorn Terelius068fc352019-02-13 22:38:25 +0100819 for (int64_t t = config_.begin_time_; t < config_.end_time_ + kStep;
820 t += kStep) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200821 while (window_index_end < packets.size() &&
822 packets[window_index_end].rtp.log_time_us() < t) {
823 uint64_t sequence_number = unwrapper_.Unwrap(
824 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800825 highest_seq_number = std::max(highest_seq_number, sequence_number);
826 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200827 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200828 while (window_index_begin < packets.size() &&
829 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
830 uint64_t sequence_number = prior_unwrapper_.Unwrap(
831 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800832 highest_prior_seq_number =
833 std::max(highest_prior_seq_number, sequence_number);
834 ++window_index_begin;
835 }
Bjorn Terelius068fc352019-02-13 22:38:25 +0100836 float x = config_.GetCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200837 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800838 if (expected_packets > 0) {
839 int64_t received_packets = window_index_end - window_index_begin;
840 int64_t lost_packets = expected_packets - received_packets;
841 float y = static_cast<float>(lost_packets) / expected_packets * 100;
842 time_series.points.emplace_back(x, y);
843 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200844 }
philipel35ba9bd2017-04-19 05:58:51 -0700845 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200846 }
847
Bjorn Terelius068fc352019-02-13 22:38:25 +0100848 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
849 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100850 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
851 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
Stefan Holmer99f8e082016-09-09 13:37:50 +0200852}
853
terelius2ee076d2017-08-15 02:04:02 -0700854void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100855 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200856 // Filter on SSRC.
857 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200858 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700859 continue;
860 }
terelius54ce6802016-07-13 06:44:41 -0700861
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100862 const std::vector<LoggedRtpPacketIncoming>& packets =
863 stream.incoming_packets;
864 if (packets.size() < 100) {
865 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
866 << packets.size() << " packets in the stream.";
867 continue;
868 }
869 int64_t end_time_us = log_segments_.empty()
870 ? std::numeric_limits<int64_t>::max()
871 : log_segments_.front().second;
872 absl::optional<uint32_t> estimated_frequency =
873 EstimateRtpClockFrequency(packets, end_time_us);
874 if (!estimated_frequency)
875 continue;
876 const double frequency_hz = *estimated_frequency;
877 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
878 RTC_LOG(LS_WARNING)
879 << "Video stream should use a 90 kHz clock but appears to use "
880 << frequency_hz / 1000 << ". Discarding.";
881 continue;
882 }
883
884 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100885 return this->config_.GetCallTimeSec(packet.log_time_us());
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100886 };
887 auto ToNetworkDelay = [frequency_hz](
888 const LoggedRtpPacketIncoming& old_packet,
889 const LoggedRtpPacketIncoming& new_packet) {
890 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
891 };
892
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200893 TimeSeries capture_time_data(
894 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
895 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100896 AccumulatePairs<LoggedRtpPacketIncoming, double>(
897 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700898 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700899
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200900 TimeSeries send_time_data(
901 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
902 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100903 AccumulatePairs<LoggedRtpPacketIncoming, double>(
904 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
905 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700906 }
907
Bjorn Terelius068fc352019-02-13 22:38:25 +0100908 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
909 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +0100910 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
911 plot->SetTitle("Incoming network delay (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700912}
913
tereliusf736d232016-08-04 10:00:11 -0700914// Plot the fraction of packets lost (as perceived by the loss-based BWE).
915void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100916 TimeSeries time_series("Fraction lost", LineStyle::kLine,
917 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200918 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100919 float x = config_.GetCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200920 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700921 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700922 }
tereliusf736d232016-08-04 10:00:11 -0700923
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200924 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +0100925 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
926 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100927 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
928 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
tereliusf736d232016-08-04 10:00:11 -0700929}
930
terelius54ce6802016-07-13 06:44:41 -0700931// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200932void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
933 // TODO(terelius): This could be provided by the parser.
934 std::multimap<int64_t, size_t> packets_in_order;
935 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
936 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
937 packets_in_order.insert(
938 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700939 }
940
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200941 auto window_begin = packets_in_order.begin();
942 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700943 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700944
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800945 if (!packets_in_order.empty()) {
946 // Calculate a moving average of the bitrate and store in a TimeSeries.
947 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
948 for (int64_t time = config_.begin_time_;
949 time < config_.end_time_ + config_.step_; time += config_.step_) {
950 while (window_end != packets_in_order.end() && window_end->first < time) {
951 bytes_in_window += window_end->second;
952 ++window_end;
953 }
954 while (window_begin != packets_in_order.end() &&
955 window_begin->first < time - config_.window_duration_) {
956 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
957 bytes_in_window -= window_begin->second;
958 ++window_begin;
959 }
960 float window_duration_in_seconds =
961 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
962 float x = config_.GetCallTimeSec(time);
963 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
964 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700965 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800966 plot->AppendTimeSeries(std::move(bitrate_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200967 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200968
969 // Overlay the outgoing REMB over incoming bitrate.
970 TimeSeries remb_series("Remb", LineStyle::kStep);
971 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100972 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200973 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
974 remb_series.points.emplace_back(x, y);
975 }
976 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
977
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800978 if (!parsed_log_.generic_packets_received().empty()) {
979 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
980 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
981 return packet.packet_length * 8.0 / 1000.0;
982 };
983 MovingAverage<LoggedGenericPacketReceived, double>(
984 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
985 &time_series);
986 plot->AppendTimeSeries(std::move(time_series));
987 }
988
Bjorn Terelius068fc352019-02-13 22:38:25 +0100989 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
990 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200991 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
992 plot->SetTitle("Incoming RTP bitrate");
993}
994
995// Plot the total bandwidth used by all RTP streams.
996void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
997 bool show_detector_state,
998 bool show_alr_state) {
999 // TODO(terelius): This could be provided by the parser.
1000 std::multimap<int64_t, size_t> packets_in_order;
1001 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1002 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
1003 packets_in_order.insert(
1004 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
1005 }
1006
1007 auto window_begin = packets_in_order.begin();
1008 auto window_end = packets_in_order.begin();
1009 size_t bytes_in_window = 0;
1010
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001011 if (!packets_in_order.empty()) {
1012 // Calculate a moving average of the bitrate and store in a TimeSeries.
1013 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
1014 for (int64_t time = config_.begin_time_;
1015 time < config_.end_time_ + config_.step_; time += config_.step_) {
1016 while (window_end != packets_in_order.end() && window_end->first < time) {
1017 bytes_in_window += window_end->second;
1018 ++window_end;
1019 }
1020 while (window_begin != packets_in_order.end() &&
1021 window_begin->first < time - config_.window_duration_) {
1022 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
1023 bytes_in_window -= window_begin->second;
1024 ++window_begin;
1025 }
1026 float window_duration_in_seconds =
1027 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
1028 float x = config_.GetCallTimeSec(time);
1029 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
1030 bitrate_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001031 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001032 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -07001033 }
1034
terelius8058e582016-07-25 01:32:41 -07001035 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001036 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
1037 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001038 float x = config_.GetCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001039 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
1040 loss_series.points.emplace_back(x, y);
1041 }
philipel10fc0e62017-04-11 01:50:23 -07001042
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001043 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
1044 IntervalSeries overusing_series("Overusing", "#ff8e82",
1045 IntervalSeries::kHorizontal);
1046 IntervalSeries underusing_series("Underusing", "#5092fc",
1047 IntervalSeries::kHorizontal);
1048 IntervalSeries normal_series("Normal", "#c4ffc4",
1049 IntervalSeries::kHorizontal);
1050 IntervalSeries* last_series = &normal_series;
1051 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -07001052
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001053 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -07001054
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001055 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001056 float x = config_.GetCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001057 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -07001058
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001059 if (last_detector_state != delay_update.detector_state) {
1060 last_series->intervals.emplace_back(last_detector_switch, x);
1061 last_detector_state = delay_update.detector_state;
1062 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -07001063
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001064 switch (delay_update.detector_state) {
1065 case BandwidthUsage::kBwNormal:
1066 last_series = &normal_series;
1067 break;
1068 case BandwidthUsage::kBwUnderusing:
1069 last_series = &underusing_series;
1070 break;
1071 case BandwidthUsage::kBwOverusing:
1072 last_series = &overusing_series;
1073 break;
1074 case BandwidthUsage::kLast:
1075 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +02001076 }
1077 }
philipel23c7f252017-07-14 06:30:03 -07001078
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001079 delay_series.points.emplace_back(x, y);
1080 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +02001081
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001082 RTC_CHECK(last_series);
Bjorn Terelius068fc352019-02-13 22:38:25 +01001083 last_series->intervals.emplace_back(last_detector_switch, config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001084
1085 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
1086 PointStyle::kHighlight);
1087 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001088 float x = config_.GetCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001089 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
1090 created_series.points.emplace_back(x, y);
1091 }
1092
1093 TimeSeries result_series("Probing results.", LineStyle::kNone,
1094 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001095 for (auto& result : parsed_log_.bwe_probe_success_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001096 float x = config_.GetCallTimeSec(result.log_time_us());
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001097 float y = static_cast<float>(result.bitrate_bps) / 1000;
1098 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001099 }
1100
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001101 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1102 PointStyle::kHighlight);
1103 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001104 float x = config_.GetCallTimeSec(failure.log_time_us());
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001105 probe_failures_series.points.emplace_back(x, 0);
1106 }
1107
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001108 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1109 bool previously_in_alr = false;
1110 int64_t alr_start = 0;
1111 for (auto& alr : parsed_log_.alr_state_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001112 float y = config_.GetCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001113 if (!previously_in_alr && alr.in_alr) {
1114 alr_start = alr.log_time_us();
1115 previously_in_alr = true;
1116 } else if (previously_in_alr && !alr.in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001117 float x = config_.GetCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +01001118 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001119 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +00001120 }
Björn Tereliusff612732018-04-25 14:23:01 +00001121 }
1122
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001123 if (previously_in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001124 float x = config_.GetCallTimeSec(alr_start);
1125 float y = config_.GetCallTimeSec(config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001126 alr_state.intervals.emplace_back(x, y);
1127 }
1128
1129 if (show_detector_state) {
1130 plot->AppendIntervalSeries(std::move(overusing_series));
1131 plot->AppendIntervalSeries(std::move(underusing_series));
1132 plot->AppendIntervalSeries(std::move(normal_series));
1133 }
1134
1135 if (show_alr_state) {
1136 plot->AppendIntervalSeries(std::move(alr_state));
1137 }
1138 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001139 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001140 plot->AppendTimeSeries(std::move(delay_series));
1141 plot->AppendTimeSeries(std::move(created_series));
1142 plot->AppendTimeSeries(std::move(result_series));
1143
1144 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001145 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001146 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001147 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001148 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001149 remb_series.points.emplace_back(x, y);
1150 }
1151 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1152
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001153 if (!parsed_log_.generic_packets_sent().empty()) {
1154 {
1155 TimeSeries time_series("Outgoing generic total bitrate",
1156 LineStyle::kLine);
1157 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1158 return packet.packet_length() * 8.0 / 1000.0;
1159 };
1160 MovingAverage<LoggedGenericPacketSent, double>(
1161 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1162 &time_series);
1163 plot->AppendTimeSeries(std::move(time_series));
1164 }
1165
1166 {
1167 TimeSeries time_series("Outgoing generic payload bitrate",
1168 LineStyle::kLine);
1169 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1170 return packet.payload_length * 8.0 / 1000.0;
1171 };
1172 MovingAverage<LoggedGenericPacketSent, double>(
1173 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1174 &time_series);
1175 plot->AppendTimeSeries(std::move(time_series));
1176 }
1177 }
1178
Bjorn Terelius068fc352019-02-13 22:38:25 +01001179 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1180 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001181 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001182 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001183}
1184
1185// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001186void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1187 Plot* plot) {
1188 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1189 // Filter on SSRC.
1190 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001191 continue;
terelius54ce6802016-07-13 06:44:41 -07001192 }
1193
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001194 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1195 LineStyle::kLine);
1196 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1197 return packet.total_length * 8.0 / 1000.0;
1198 };
terelius53dc23c2017-03-13 05:24:05 -07001199 MovingAverage<LoggedRtpPacket, double>(
Bjorn Terelius068fc352019-02-13 22:38:25 +01001200 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001201 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001202 }
1203
Bjorn Terelius068fc352019-02-13 22:38:25 +01001204 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1205 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001206 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001207 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001208}
1209
Bjorn Terelius9775a582019-02-15 17:29:58 +01001210// Plot the bitrate allocation for each temporal and spatial layer.
1211// Computed from RTCP XR target bitrate block, so the graph is only populated if
1212// those are sent.
1213void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1214 Plot* plot) {
1215 std::map<LayerDescription, TimeSeries> time_series;
1216 const auto& xr_list = parsed_log_.extended_reports(direction);
1217 for (const auto& rtcp : xr_list) {
1218 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1219 rtcp.xr.target_bitrate();
1220 if (!target_bitrate.has_value())
1221 continue;
1222 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1223 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1224 bitrate_item.temporal_layer);
1225 auto time_series_it = time_series.find(layer);
1226 if (time_series_it == time_series.end()) {
1227 std::string layer_name = GetLayerName(layer);
1228 bool inserted;
1229 std::tie(time_series_it, inserted) = time_series.insert(
1230 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1231 RTC_DCHECK(inserted);
1232 }
1233 float x = config_.GetCallTimeSec(rtcp.log_time_us());
1234 float y = bitrate_item.target_bitrate_kbps;
1235 time_series_it->second.points.emplace_back(x, y);
1236 }
1237 }
1238 for (auto& layer : time_series) {
1239 plot->AppendTimeSeries(std::move(layer.second));
1240 }
1241 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1242 "Time (s)", kLeftMargin, kRightMargin);
1243 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1244 if (direction == kIncomingPacket)
1245 plot->SetTitle("Target bitrate per incoming layer");
1246 else
1247 plot->SetTitle("Target bitrate per outgoing layer");
1248}
1249
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001250void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1251 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1252 PointStyle::kHighlight);
1253 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1254 PointStyle::kHighlight);
1255 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1256 PointStyle::kHighlight);
1257 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1258 PointStyle::kHighlight);
1259
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001260 LogBasedNetworkControllerSimulation simulation(
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001261 std::make_unique<GoogCcNetworkControllerFactory>(),
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001262 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1263 if (update.target_rate) {
1264 target_rates.points.emplace_back(
1265 config_.GetCallTimeSec(at_time.us()),
1266 update.target_rate->target_rate.kbps<float>());
1267 }
1268 });
1269
1270 simulation.ProcessEventsInLog(parsed_log_);
1271 for (const auto& logged : parsed_log_.bwe_delay_updates())
1272 delay_based.points.emplace_back(
1273 config_.GetCallTimeSec(logged.log_time_us()),
1274 logged.bitrate_bps / 1000);
1275 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1276 probe_results.points.emplace_back(
1277 config_.GetCallTimeSec(logged.log_time_us()),
1278 logged.bitrate_bps / 1000);
1279 for (const auto& logged : parsed_log_.bwe_loss_updates())
1280 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time_us()),
1281 logged.bitrate_bps / 1000);
1282
1283 plot->AppendTimeSeries(std::move(delay_based));
1284 plot->AppendTimeSeries(std::move(loss_based));
1285 plot->AppendTimeSeries(std::move(probe_results));
1286 plot->AppendTimeSeries(std::move(target_rates));
1287
1288 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1289 "Time (s)", kLeftMargin, kRightMargin);
1290 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1291 plot->SetTitle("Simulated BWE behavior");
1292}
1293
Bjorn Terelius28db2662017-10-04 14:22:43 +02001294void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001295 using RtpPacketType = LoggedRtpPacketOutgoing;
1296 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001297
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001298 // TODO(terelius): This could be provided by the parser.
1299 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1300 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1301 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1302 outgoing_rtp.insert(
1303 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001304 }
1305
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001306 const std::vector<TransportFeedbackType>& incoming_rtcp =
1307 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001308
1309 SimulatedClock clock(0);
1310 BitrateObserver observer;
Danil Chapovalov83bbe912019-08-07 12:24:53 +02001311 RtcEventLogNull null_event_log;
nisse0245da02016-11-30 03:35:20 -08001312 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001313 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001314 TransportFeedbackAdapter transport_feedback;
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001315 auto factory = GoogCcNetworkControllerFactory();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001316 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001317 // TODO(holmer): Log the call config and use that here instead.
1318 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001319 NetworkControllerConfig cc_config;
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001320 cc_config.constraints.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
Danil Chapovalovcad3e0e2020-02-17 18:46:07 +01001321 cc_config.constraints.starting_rate =
1322 DataRate::BitsPerSec(kDefaultStartBitrateBps);
Sebastian Jansson2db5fc02019-04-30 14:17:45 +02001323 cc_config.event_log = &null_event_log;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001324 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001325
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001326 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1327 PointStyle::kHighlight);
1328 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1329 PointStyle::kHighlight);
1330 TimeSeries acked_estimate_time_series(
1331 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001332
1333 auto rtp_iterator = outgoing_rtp.begin();
1334 auto rtcp_iterator = incoming_rtcp.begin();
1335
1336 auto NextRtpTime = [&]() {
1337 if (rtp_iterator != outgoing_rtp.end())
1338 return static_cast<int64_t>(rtp_iterator->first);
1339 return std::numeric_limits<int64_t>::max();
1340 };
1341
1342 auto NextRtcpTime = [&]() {
1343 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001344 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001345 return std::numeric_limits<int64_t>::max();
1346 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001347 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001348
1349 auto NextProcessTime = [&]() {
1350 if (rtcp_iterator != incoming_rtcp.end() ||
1351 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001352 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001353 }
1354 return std::numeric_limits<int64_t>::max();
1355 };
1356
Stefan Holmer492ee282016-10-27 17:19:20 +02001357 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001358#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001359 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001360 // The event_log_visualizer should normally not be compiled with
1361 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
Björn Terelius251b0dc2019-11-11 21:00:18 +01001362 // However, compiling with BWE_TEST_LOGGING, running with --plot=sendside_bwe
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001363 // and piping the output to plot_dynamics.py can be used as a hack to get the
1364 // internal state of various BWE components. In this case, it is important
1365 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
Sebastian Jansson4ad51d82019-06-11 11:24:40 +02001366 // GoogCcNetworkController since that would lead to duplicate outputs.
Björn Terelius251b0dc2019-11-11 21:00:18 +01001367 std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1368 acknowledged_bitrate_estimator(
1369 AcknowledgedBitrateEstimatorInterface::Create(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001370#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001371 int64_t time_us =
1372 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001373 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001374 while (time_us != std::numeric_limits<int64_t>::max()) {
1375 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001376 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1377 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1378 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1379 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1380 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
Erik Språng30a276b2019-04-23 12:00:11 +02001381 RtpPacketSendInfo packet_info;
1382 packet_info.ssrc = rtp_packet.rtp.header.ssrc;
Bjorn Tereliusf2e9cab2019-05-27 16:44:09 +02001383 packet_info.transport_sequence_number =
Erik Språng30a276b2019-04-23 12:00:11 +02001384 rtp_packet.rtp.header.extension.transportSequenceNumber;
1385 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
Erik Språng30a276b2019-04-23 12:00:11 +02001386 packet_info.length = rtp_packet.rtp.total_length;
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001387 transport_feedback.AddPacket(
Erik Språng30a276b2019-04-23 12:00:11 +02001388 packet_info,
1389 0u, // Per packet overhead bytes.
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001390 Timestamp::Micros(rtp_packet.rtp.log_time_us()));
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001391 rtc::SentPacket sent_packet(
1392 rtp_packet.rtp.header.extension.transportSequenceNumber,
1393 rtp_packet.rtp.log_time_us() / 1000);
1394 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1395 if (sent_msg)
1396 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1397 }
1398 ++rtp_iterator;
1399 }
Stefan Holmer13181032016-07-29 14:48:54 +02001400 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001401 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001402
1403 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001404 rtcp_iterator->transport_feedback,
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001405 Timestamp::Millis(clock.TimeInMilliseconds()));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001406 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001407 if (feedback_msg) {
1408 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001409 std::vector<PacketResult> feedback =
1410 feedback_msg->SortedByReceiveTime();
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001411 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001412#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Björn Terelius251b0dc2019-11-11 21:00:18 +01001413 acknowledged_bitrate_estimator->IncomingPacketFeedbackVector(
1414 feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001415#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001416 for (const PacketResult& packet : feedback)
1417 acked_bitrate.Update(packet.sent_packet.size.bytes(),
1418 packet.receive_time.ms());
1419 bitrate_bps = acked_bitrate.Rate(feedback.back().receive_time.ms());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001420 }
Stefan Holmer13181032016-07-29 14:48:54 +02001421 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001422
Bjorn Terelius068fc352019-02-13 22:38:25 +01001423 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001424 float y = bitrate_bps.value_or(0) / 1000;
1425 acked_time_series.points.emplace_back(x, y);
1426#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Björn Terelius251b0dc2019-11-11 21:00:18 +01001427 y = acknowledged_bitrate_estimator->bitrate()
Sebastian Jansson88290ae2019-06-20 12:26:31 +02001428 .value_or(DataRate::Zero())
1429 .kbps();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001430 acked_estimate_time_series.points.emplace_back(x, y);
1431#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001432 ++rtcp_iterator;
1433 }
stefanc3de0332016-08-02 07:22:17 -07001434 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1435 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001436 ProcessInterval msg;
Danil Chapovalov0c626af2020-02-10 11:16:00 +01001437 msg.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001438 observer.Update(goog_cc->OnProcessInterval(msg));
1439 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001440 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001441 if (observer.GetAndResetBitrateUpdated() ||
1442 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001443 uint32_t y = observer.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001444 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001445 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001446 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001447 }
1448 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1449 }
1450 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001451 plot->AppendTimeSeries(std::move(time_series));
1452 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001453 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001454
Bjorn Terelius068fc352019-02-13 22:38:25 +01001455 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1456 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001457 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001458 plot->SetTitle("Simulated send-side BWE behavior");
1459}
1460
1461void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001462 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001463 class RembInterceptingPacketRouter : public PacketRouter {
1464 public:
1465 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1466 uint32_t bitrate_bps) override {
1467 last_bitrate_bps_ = bitrate_bps;
1468 bitrate_updated_ = true;
1469 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1470 }
1471 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1472 bool GetAndResetBitrateUpdated() {
1473 bool bitrate_updated = bitrate_updated_;
1474 bitrate_updated_ = false;
1475 return bitrate_updated;
1476 }
1477
1478 private:
1479 uint32_t last_bitrate_bps_;
1480 bool bitrate_updated_;
1481 };
1482
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001483 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001484
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001485 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1486 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1487 for (const auto& rtp_packet : stream.incoming_packets)
1488 incoming_rtp.insert(
1489 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001490 }
1491 }
1492
1493 SimulatedClock clock(0);
1494 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001495 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001496 // Is this intentional?
1497 ReceiveSideCongestionController rscc(&clock, &packet_router);
1498 // TODO(holmer): Log the call config and use that here instead.
1499 // static const uint32_t kDefaultStartBitrateBps = 300000;
1500 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1501
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001502 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1503 PointStyle::kHighlight);
1504 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001505
1506 RateStatistics acked_bitrate(250, 8000);
1507 int64_t last_update_us = 0;
1508 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001509 const RtpPacketType& packet = *kv.second;
1510 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1511 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1512 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001513 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001514 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001515 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001516 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001517 if (bitrate_bps) {
1518 uint32_t y = *bitrate_bps / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001519 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001520 acked_time_series.points.emplace_back(x, y);
1521 }
1522 if (packet_router.GetAndResetBitrateUpdated() ||
1523 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1524 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001525 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001526 time_series.points.emplace_back(x, y);
1527 last_update_us = clock.TimeInMicroseconds();
1528 }
1529 }
1530 // Add the data set to the plot.
1531 plot->AppendTimeSeries(std::move(time_series));
1532 plot->AppendTimeSeries(std::move(acked_time_series));
1533
Bjorn Terelius068fc352019-02-13 22:38:25 +01001534 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1535 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001536 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1537 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001538}
1539
tereliuse34c19c2016-08-15 08:47:14 -07001540void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001541 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001542 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001543 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1544 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001545
stefana0a8ed72017-09-06 02:06:32 -07001546 int64_t prev_y = 0;
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001547 std::vector<MatchedSendArrivalTimes> matched_rtp_rtcp =
1548 GetNetworkTrace(parsed_log_);
1549 absl::c_stable_sort(matched_rtp_rtcp, [](const MatchedSendArrivalTimes& a,
1550 const MatchedSendArrivalTimes& b) {
philipel3574d052019-11-18 14:38:13 +01001551 return a.feedback_arrival_time_ms < b.feedback_arrival_time_ms ||
1552 (a.feedback_arrival_time_ms == b.feedback_arrival_time_ms &&
1553 a.arrival_time_ms < b.arrival_time_ms);
Björn Tereliusc69c1bb2019-10-11 15:06:58 +02001554 });
1555 for (const auto& packet : matched_rtp_rtcp) {
Sebastian Jansson74f96ec2019-10-29 12:57:54 +01001556 if (packet.arrival_time_ms == MatchedSendArrivalTimes::kNotReceived)
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001557 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001558 float x = config_.GetCallTimeSec(1000 * packet.feedback_arrival_time_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001559 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1560 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001561 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1562 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1563 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001564 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001565 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001566
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001567 // We assume that the base network delay (w/o queues) is equal to half
1568 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
Mirko Bonadei604e75c2019-07-25 11:55:47 +02001569 // observed 1-ways delay and add half the minimum RTT.
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001570 const int64_t estimated_clock_offset_ms =
1571 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001572 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001573 point.y -= estimated_clock_offset_ms;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001574
stefanc3de0332016-08-02 07:22:17 -07001575 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001576 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
stefanc3de0332016-08-02 07:22:17 -07001577
Bjorn Terelius068fc352019-02-13 22:38:25 +01001578 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1579 "Time (s)", kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001580 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +01001581 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001582}
stefan08383272016-12-20 08:51:52 -08001583
Bjorn Terelius0295a962017-10-25 17:42:41 +02001584void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001585 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1586 const std::vector<LoggedRtpPacketOutgoing>& packets =
1587 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001588
Konrad Hofbauerbfb735b2019-04-16 11:12:11 +02001589 if (IsRtxSsrc(kOutgoingPacket, stream.ssrc)) {
1590 continue;
1591 }
1592
Bjorn Terelius0295a962017-10-25 17:42:41 +02001593 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001594 RTC_LOG(LS_WARNING)
1595 << "Can't estimate a the RTP clock frequency or the "
1596 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001597 continue;
1598 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001599 int64_t end_time_us = log_segments_.empty()
1600 ? std::numeric_limits<int64_t>::max()
1601 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001602 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001603 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001604 if (!estimated_frequency)
1605 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001606 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1607 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001608 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001609 << "Video stream should use a 90 kHz clock but appears to use "
1610 << *estimated_frequency / 1000 << ". Discarding.";
1611 continue;
1612 }
1613
1614 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001615 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001616 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001617 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001618 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1619 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001620 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1621 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1622 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001623 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001624 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001625 first_capture_timestamp) /
1626 *estimated_frequency * 1000;
1627 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001628 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1629 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001630 float x = config_.GetCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001631 float y = send_time_ms - capture_time_ms;
1632 pacer_delay_series.points.emplace_back(x, y);
1633 }
1634 plot->AppendTimeSeries(std::move(pacer_delay_series));
1635 }
1636
Bjorn Terelius068fc352019-02-13 22:38:25 +01001637 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1638 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001639 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1640 plot->SetTitle(
1641 "Delay from capture to send time. (First packet normalized to 0.)");
1642}
1643
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001644void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1645 Plot* plot) {
1646 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1647 TimeSeries rtp_timestamps(
1648 GetStreamName(direction, stream.ssrc) + " capture-time",
1649 LineStyle::kLine, PointStyle::kHighlight);
1650 for (const auto& packet : stream.packet_view) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001651 float x = config_.GetCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001652 float y = packet.header.timestamp;
1653 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001654 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001655 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001656
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001657 TimeSeries rtcp_timestamps(
1658 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1659 LineStyle::kLine, PointStyle::kHighlight);
1660 // TODO(terelius): Why only sender reports?
1661 const auto& sender_reports = parsed_log_.sender_reports(direction);
1662 for (const auto& rtcp : sender_reports) {
1663 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1664 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001665 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001666 float y = rtcp.sr.rtp_timestamp();
1667 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001668 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001669 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001670 }
1671
Bjorn Terelius068fc352019-02-13 22:38:25 +01001672 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1673 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001674 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1675 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001676}
michaelt6e5b2192017-02-22 07:33:27 -08001677
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001678void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1679 PacketDirection direction,
1680 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1681 std::string title,
1682 std::string yaxis_label,
1683 Plot* plot) {
1684 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1685 const auto& sender_reports = parsed_log_.sender_reports(direction);
1686 for (const auto& rtcp : sender_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001687 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001688 uint32_t ssrc = rtcp.sr.sender_ssrc();
1689 for (const auto& block : rtcp.sr.report_blocks()) {
1690 float y = fy(block);
1691 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1692 bool inserted;
1693 if (sr_report_it == sr_reports_by_ssrc.end()) {
1694 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1695 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1696 LineStyle::kLine, PointStyle::kHighlight));
1697 }
1698 sr_report_it->second.points.emplace_back(x, y);
1699 }
1700 }
1701 for (auto& kv : sr_reports_by_ssrc) {
1702 plot->AppendTimeSeries(std::move(kv.second));
1703 }
1704
1705 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1706 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1707 for (const auto& rtcp : receiver_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001708 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001709 uint32_t ssrc = rtcp.rr.sender_ssrc();
1710 for (const auto& block : rtcp.rr.report_blocks()) {
1711 float y = fy(block);
1712 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1713 bool inserted;
1714 if (rr_report_it == rr_reports_by_ssrc.end()) {
1715 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1716 ssrc,
1717 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1718 LineStyle::kLine, PointStyle::kHighlight));
1719 }
1720 rr_report_it->second.points.emplace_back(x, y);
1721 }
1722 }
1723 for (auto& kv : rr_reports_by_ssrc) {
1724 plot->AppendTimeSeries(std::move(kv.second));
1725 }
1726
Bjorn Terelius068fc352019-02-13 22:38:25 +01001727 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1728 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001729 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1730 plot->SetTitle(title);
1731}
1732
michaelt6e5b2192017-02-22 07:33:27 -08001733void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001734 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1735 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001736 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001737 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001738 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001739 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001740 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001741 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001742 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001743 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001744 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001745 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001746 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001747 ToCallTime, GetAnaBitrateBps,
1748 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001749 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001750 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1751 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001752 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1753 plot->SetTitle("Reported audio encoder target bitrate");
1754}
1755
1756void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001757 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1758 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001759 auto GetAnaFrameLengthMs =
1760 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001761 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001762 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001763 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001764 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001765 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001766 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001767 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001768 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001769 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001770 ToCallTime, GetAnaFrameLengthMs,
1771 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001772 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001773 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1774 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001775 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1776 plot->SetTitle("Reported audio encoder frame length");
1777}
1778
terelius2ee076d2017-08-15 02:04:02 -07001779void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001780 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001781 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001782 auto GetAnaPacketLoss =
1783 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001784 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001785 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001786 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001787 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001788 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001789 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001790 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001791 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001792 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001793 ToCallTime, GetAnaPacketLoss,
1794 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001795 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001796 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1797 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001798 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1799 kTopMargin);
1800 plot->SetTitle("Reported audio encoder lost packets");
1801}
1802
1803void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001804 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1805 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001806 auto GetAnaFecEnabled =
1807 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001808 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001809 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001810 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001811 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001812 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001813 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001814 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001815 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001816 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001817 ToCallTime, GetAnaFecEnabled,
1818 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001819 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001820 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1821 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001822 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1823 plot->SetTitle("Reported audio encoder FEC");
1824}
1825
1826void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001827 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1828 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001829 auto GetAnaDtxEnabled =
1830 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001831 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001832 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001833 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001834 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001835 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001836 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001837 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001838 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001839 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001840 ToCallTime, GetAnaDtxEnabled,
1841 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001842 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001843 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1844 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001845 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1846 plot->SetTitle("Reported audio encoder DTX");
1847}
1848
1849void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001850 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1851 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001852 auto GetAnaNumChannels =
1853 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001854 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001855 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001856 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001857 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001858 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001859 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001860 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001861 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001862 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001863 ToCallTime, GetAnaNumChannels,
1864 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001865 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001866 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1867 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001868 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1869 kBottomMargin, kTopMargin);
1870 plot->SetTitle("Reported audio encoder number of channels");
1871}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001872
1873class NetEqStreamInput : public test::NetEqInput {
1874 public:
1875 // Does not take any ownership, and all pointers must refer to valid objects
1876 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001877 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001878 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001879 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001880 : packet_stream_(*packet_stream),
1881 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001882 output_events_it_(output_events->begin()),
1883 output_events_end_(output_events->end()),
1884 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001885 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001886 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001887 }
1888
Danil Chapovalov431abd92018-06-18 12:54:17 +02001889 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001890 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001891 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001892 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001893 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001894 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001895 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001896 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001897 }
1898
Danil Chapovalov431abd92018-06-18 12:54:17 +02001899 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001900 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001901 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001902 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001903 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001904 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001905 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001906 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001907 }
1908
1909 std::unique_ptr<PacketData> PopPacket() override {
1910 if (packet_stream_it_ == packet_stream_.end()) {
1911 return std::unique_ptr<PacketData>();
1912 }
1913 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001914 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001915 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001916
1917 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1918 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001919 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1920 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001921 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1922
1923 ++packet_stream_it_;
1924 return packet_data;
1925 }
1926
1927 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001928 if (output_events_it_ != output_events_end_) {
1929 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001930 }
1931 }
1932
1933 bool ended() const override { return !NextEventTime(); }
1934
Danil Chapovalov431abd92018-06-18 12:54:17 +02001935 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001936 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001937 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001938 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001939 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001940 }
1941
1942 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001943 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1944 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001945 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1946 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001947 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001948};
1949
1950namespace {
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001951
1952// Factory to create a "replacement decoder" that produces the decoded audio
1953// by reading from a file rather than from the encoded payloads.
1954class ReplacementAudioDecoderFactory : public AudioDecoderFactory {
1955 public:
1956 ReplacementAudioDecoderFactory(const absl::string_view replacement_file_name,
1957 int file_sample_rate_hz)
1958 : replacement_file_name_(replacement_file_name),
1959 file_sample_rate_hz_(file_sample_rate_hz) {}
1960
1961 std::vector<AudioCodecSpec> GetSupportedDecoders() override {
1962 RTC_NOTREACHED();
1963 return {};
1964 }
1965
1966 bool IsSupportedDecoder(const SdpAudioFormat& format) override {
1967 return true;
1968 }
1969
1970 std::unique_ptr<AudioDecoder> MakeAudioDecoder(
1971 const SdpAudioFormat& format,
1972 absl::optional<AudioCodecPairId> codec_pair_id) override {
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001973 auto replacement_file = std::make_unique<test::ResampleInputAudioFile>(
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001974 replacement_file_name_, file_sample_rate_hz_);
1975 replacement_file->set_output_rate_hz(48000);
Mirko Bonadei317a1f02019-09-17 17:06:18 +02001976 return std::make_unique<test::FakeDecodeFromFile>(
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001977 std::move(replacement_file), 48000, false);
1978 }
1979
1980 private:
1981 const std::string replacement_file_name_;
1982 const int file_sample_rate_hz_;
1983};
1984
henrik.lundin3c938fc2017-06-14 06:09:58 -07001985// Creates a NetEq test object and all necessary input and output helpers. Runs
1986// the test and returns the NetEqDelayAnalyzer object that was used to
1987// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001988std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001989 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001990 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001991 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001992 const std::string& replacement_file_name,
1993 int file_sample_rate_hz) {
1994 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001995 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001996
1997 constexpr int kReplacementPt = 127;
1998 std::set<uint8_t> cn_types;
1999 std::set<uint8_t> forbidden_types;
2000 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
2001 cn_types, forbidden_types));
2002
2003 NetEq::Config config;
2004 config.max_packets_in_buffer = 200;
2005 config.enable_fast_accelerate = true;
2006
2007 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
2008
Niels Möller3f651d82018-12-19 15:06:17 +01002009 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01002010 new rtc::RefCountedObject<ReplacementAudioDecoderFactory>(
2011 replacement_file_name, file_sample_rate_hz);
Niels Möller3f651d82018-12-19 15:06:17 +01002012
Niels Möller05543682019-01-10 16:55:06 +01002013 test::NetEqTest::DecoderMap codecs = {
2014 {kReplacementPt, SdpAudioFormat("l16", 48000, 1)}};
henrik.lundin3c938fc2017-06-14 06:09:58 -07002015
2016 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
2017 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02002018 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
2019 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002020 test::DefaultNetEqTestErrorCallback error_cb;
2021 test::NetEqTest::Callbacks callbacks;
2022 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02002023 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
2024 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07002025
Ivo Creusencee751a2020-01-16 17:17:09 +01002026 test::NetEqTest test(config, decoder_factory, codecs, /*text_log=*/nullptr,
2027 /*factory=*/nullptr, std::move(input), std::move(output),
2028 callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002029 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02002030 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07002031}
2032} // namespace
2033
Minyue Lic6ff7572018-05-04 09:46:44 +02002034EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07002035 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02002036 int file_sample_rate_hz) const {
2037 NetEqStatsGetterMap neteq_stats;
2038
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002039 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02002040 const uint32_t ssrc = stream.ssrc;
2041 if (!IsAudioSsrc(kIncomingPacket, ssrc))
2042 continue;
2043 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
2044 &stream.incoming_packets;
2045 if (audio_packets == nullptr) {
2046 // No incoming audio stream found.
2047 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002048 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07002049
Minyue Li27e2b7d2018-05-07 15:20:24 +02002050 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
2051
2052 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
2053 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
2054 if (output_events_it == parsed_log_.audio_playout_events().end()) {
2055 // Could not find output events with SSRC matching the input audio stream.
2056 // Using the first available stream of output events.
2057 output_events_it = parsed_log_.audio_playout_events().cbegin();
2058 }
2059
Danil Chapovalov431abd92018-06-18 12:54:17 +02002060 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02002061 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02002062 ? absl::nullopt
2063 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002064
2065 neteq_stats[ssrc] = CreateNetEqTestAndRun(
2066 audio_packets, &output_events_it->second, end_time_ms,
2067 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002068 }
2069
Minyue Lic6ff7572018-05-04 09:46:44 +02002070 return neteq_stats;
2071}
2072
Minyue Lic97933f2018-08-10 12:51:15 +02002073// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
2074// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02002075void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02002076 uint32_t ssrc,
2077 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02002078 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02002079 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
2080 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
2081 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
2082 test::NetEqDelayAnalyzer::Delays target_delay_ms;
2083
Minyue Li01d2a672018-06-21 21:17:19 +02002084 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02002085 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
2086 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002087
Minyue Lic97933f2018-08-10 12:51:15 +02002088 TimeSeries time_series_packet_arrival("packet arrival delay",
2089 LineStyle::kLine);
2090 TimeSeries time_series_relative_packet_arrival(
2091 "Relative packet arrival delay", LineStyle::kLine);
2092 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
2093 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
2094 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02002095
2096 for (const auto& data : arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002097 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002098 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002099 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002100 }
2101 for (const auto& data : corrected_arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002102 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002103 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002104 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02002105 TimeSeriesPoint(x, y));
2106 }
2107 for (const auto& data : playout_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002108 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002109 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002110 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002111 }
2112 for (const auto& data : target_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002113 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002114 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002115 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002116 }
2117
Minyue Lic97933f2018-08-10 12:51:15 +02002118 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
2119 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
2120 plot->AppendTimeSeries(std::move(time_series_play_time));
2121 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002122
Bjorn Terelius068fc352019-02-13 22:38:25 +01002123 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2124 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002125 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
2126 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002127 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
2128}
2129
Minyue Lic9ac93f2018-06-26 13:01:32 +02002130template <typename NetEqStatsType>
2131void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02002132 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02002133 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
2134 const test::NetEqStatsGetter*)> data_extractor,
2135 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02002136 const std::string& plot_name,
2137 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02002138 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02002139
2140 for (const auto& st : neteq_stats) {
2141 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02002142 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
2143 data_extractor(st.second.get());
2144 for (const auto& data : *data_vector) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002145 const float time =
2146 config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Lic9ac93f2018-06-26 13:01:32 +02002147 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002148 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02002149 }
2150 }
2151
2152 for (auto& series : time_series) {
2153 series.second.label = GetStreamName(kIncomingPacket, series.first);
2154 series.second.line_style = LineStyle::kLine;
2155 plot->AppendTimeSeries(std::move(series.second));
2156 }
2157
Bjorn Terelius068fc352019-02-13 22:38:25 +01002158 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2159 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002160 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002161 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002162}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002163
Minyue Lic9ac93f2018-06-26 13:01:32 +02002164void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
2165 const NetEqStatsGetterMap& neteq_stats,
2166 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
2167 const std::string& plot_name,
2168 Plot* plot) const {
2169 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
2170 neteq_stats,
2171 [](const test::NetEqStatsGetter* stats_getter) {
2172 return stats_getter->stats();
2173 },
2174 stats_extractor, plot_name, plot);
2175}
2176
2177void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
2178 const NetEqStatsGetterMap& neteq_stats,
2179 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
2180 const std::string& plot_name,
2181 Plot* plot) const {
2182 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
2183 neteq_stats,
2184 [](const test::NetEqStatsGetter* stats_getter) {
2185 return stats_getter->lifetime_stats();
2186 },
2187 stats_extractor, plot_name, plot);
2188}
2189
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002190void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
2191 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002192 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002193 if (configs_by_cp_id.find(config.candidate_pair_id) ==
2194 configs_by_cp_id.end()) {
2195 const std::string candidate_pair_desc =
2196 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08002197 configs_by_cp_id[config.candidate_pair_id] =
2198 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
2199 candidate_pair_desc,
2200 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002201 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2202 candidate_pair_desc;
2203 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002204 float x = config_.GetCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002205 float y = static_cast<float>(config.type);
2206 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
2207 }
2208
2209 // TODO(qingsi): There can be a large number of candidate pairs generated by
2210 // certain calls and the frontend cannot render the chart in this case due to
2211 // the failure of generating a palette with the same number of colors.
2212 for (auto& kv : configs_by_cp_id) {
2213 plot->AppendTimeSeries(std::move(kv.second));
2214 }
2215
Bjorn Terelius068fc352019-02-13 22:38:25 +01002216 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2217 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002218 plot->SetSuggestedYAxis(0, 3, "Config Type", kBottomMargin, kTopMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002219 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002220 plot->SetYAxisTickLabels(
2221 {{static_cast<float>(IceCandidatePairConfigType::kAdded), "ADDED"},
2222 {static_cast<float>(IceCandidatePairConfigType::kUpdated), "UPDATED"},
2223 {static_cast<float>(IceCandidatePairConfigType::kDestroyed),
2224 "DESTROYED"},
2225 {static_cast<float>(IceCandidatePairConfigType::kSelected),
2226 "SELECTED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002227}
2228
2229std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
2230 uint32_t candidate_pair_id) {
2231 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
2232 candidate_pair_desc_by_id_.end()) {
2233 return candidate_pair_desc_by_id_[candidate_pair_id];
2234 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002235 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002236 // TODO(qingsi): Add the handling of the "Updated" config event after the
2237 // visualization of property change for candidate pairs is introduced.
2238 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
2239 candidate_pair_desc_by_id_.end()) {
2240 const std::string candidate_pair_desc =
2241 GetCandidatePairLogDescriptionAsString(config);
2242 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2243 candidate_pair_desc;
2244 }
2245 }
2246 return candidate_pair_desc_by_id_[candidate_pair_id];
2247}
2248
2249void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002250 constexpr int kEventTypeOffset =
2251 static_cast<int>(IceCandidatePairConfigType::kNumValues);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002252 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002253 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002254 if (checks_by_cp_id.find(event.candidate_pair_id) ==
2255 checks_by_cp_id.end()) {
2256 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08002257 "[" + std::to_string(event.candidate_pair_id) + "]" +
2258 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002259 LineStyle::kNone, PointStyle::kHighlight);
2260 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002261 float x = config_.GetCallTimeSec(event.log_time_us());
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002262 float y = static_cast<float>(event.type) + kEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002263 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2264 }
2265
2266 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2267 for (auto& kv : checks_by_cp_id) {
2268 plot->AppendTimeSeries(std::move(kv.second));
2269 }
2270
Bjorn Terelius068fc352019-02-13 22:38:25 +01002271 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2272 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002273 plot->SetSuggestedYAxis(0, 4, "Connectivity State", kBottomMargin,
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002274 kTopMargin);
2275 plot->SetTitle("[IceEventLog] ICE connectivity checks");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002276
2277 plot->SetYAxisTickLabels(
2278 {{static_cast<float>(IceCandidatePairEventType::kCheckSent) +
2279 kEventTypeOffset,
2280 "CHECK SENT"},
2281 {static_cast<float>(IceCandidatePairEventType::kCheckReceived) +
2282 kEventTypeOffset,
2283 "CHECK RECEIVED"},
2284 {static_cast<float>(IceCandidatePairEventType::kCheckResponseSent) +
2285 kEventTypeOffset,
2286 "RESPONSE SENT"},
2287 {static_cast<float>(IceCandidatePairEventType::kCheckResponseReceived) +
2288 kEventTypeOffset,
2289 "RESPONSE RECEIVED"}});
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002290}
2291
Zach Stein10a58012018-12-07 12:26:28 -08002292void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
2293 TimeSeries states("DTLS Transport State", LineStyle::kNone,
2294 PointStyle::kHighlight);
2295 for (const auto& event : parsed_log_.dtls_transport_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002296 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002297 float y = static_cast<float>(event.dtls_transport_state);
2298 states.points.emplace_back(x, y);
2299 }
2300 plot->AppendTimeSeries(std::move(states));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002301 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2302 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002303 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002304 "Transport State", kBottomMargin, kTopMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002305 plot->SetTitle("DTLS Transport State");
Bjorn Tereliusf640b872019-07-24 15:46:39 +02002306 plot->SetYAxisTickLabels(
2307 {{static_cast<float>(DtlsTransportState::kNew), "NEW"},
2308 {static_cast<float>(DtlsTransportState::kConnecting), "CONNECTING"},
2309 {static_cast<float>(DtlsTransportState::kConnected), "CONNECTED"},
2310 {static_cast<float>(DtlsTransportState::kClosed), "CLOSED"},
2311 {static_cast<float>(DtlsTransportState::kFailed), "FAILED"}});
Zach Stein10a58012018-12-07 12:26:28 -08002312}
2313
2314void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2315 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2316 PointStyle::kHighlight);
2317 for (const auto& event : parsed_log_.dtls_writable_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002318 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002319 float y = static_cast<float>(event.writable);
2320 writable.points.emplace_back(x, y);
2321 }
2322 plot->AppendTimeSeries(std::move(writable));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002323 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2324 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002325 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2326 plot->SetTitle("DTLS Writable State");
2327}
2328
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002329void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002330 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002331 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2332 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2333 }
2334 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2335 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2336 }
2337 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2338 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2339 }
2340 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2341 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2342 }
2343 for (const auto& alert : incoming_seq_num_jumps_) {
2344 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2345 }
2346 for (const auto& alert : incoming_capture_time_jumps_) {
2347 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2348 }
2349 for (const auto& alert : outgoing_seq_num_jumps_) {
2350 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2351 }
2352 for (const auto& alert : outgoing_capture_time_jumps_) {
2353 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2354 }
2355 for (const auto& alert : outgoing_high_loss_alerts_) {
2356 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002357 }
2358 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2359}
2360
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002361void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2362 // With 100 packets/s (~800kbps), false positives would require 10 s without
2363 // data.
2364 constexpr int64_t kMaxSeqNumJump = 1000;
2365 // With a 90 kHz clock, false positives would require 10 s without data.
2366 constexpr int64_t kMaxCaptureTimeJump = 900000;
2367
2368 int64_t end_time_us = log_segments_.empty()
2369 ? std::numeric_limits<int64_t>::max()
2370 : log_segments_.front().second;
2371
2372 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002373 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002374 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002375 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002376 // Check for gaps in sequence numbers and capture timestamps.
2377 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2378 for (const auto& packet : stream.packet_view) {
2379 if (packet.log_time_us() > end_time_us) {
2380 // Only process the first (LOG_START, LOG_END) segment.
2381 break;
2382 }
2383
2384 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2385 if (last_seq_num.has_value() &&
2386 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002387 Alert_SeqNumJump(direction,
2388 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002389 packet.header.ssrc);
2390 }
2391 last_seq_num.emplace(seq_num);
2392
2393 int64_t capture_time =
2394 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2395 if (last_capture_time.has_value() &&
2396 std::abs(capture_time - last_capture_time.value()) >
2397 kMaxCaptureTimeJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002398 Alert_CaptureTimeJump(direction,
2399 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002400 packet.header.ssrc);
2401 }
2402 last_capture_time.emplace(capture_time);
2403 }
2404 }
2405}
2406
2407void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2408 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2409 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2410 int64_t end_time_us = log_segments_.empty()
2411 ? std::numeric_limits<int64_t>::max()
2412 : log_segments_.front().second;
2413
2414 // TODO(terelius): The parser could provide a list of all packets, ordered
2415 // by time, for each direction.
2416 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2417 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2418 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2419 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2420 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002421 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002422 for (const auto& kv : rtp_in_direction) {
2423 int64_t timestamp = kv.first;
2424 if (timestamp > end_time_us) {
2425 // Only process the first (LOG_START, LOG_END) segment.
2426 break;
2427 }
2428 int64_t duration = timestamp - last_rtp_time.value_or(0);
2429 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2430 // No packet sent/received for more than 500 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002431 Alert_RtpLogTimeGap(direction, config_.GetCallTimeSec(timestamp),
2432 duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002433 }
2434 last_rtp_time.emplace(timestamp);
2435 }
2436
Danil Chapovalov431abd92018-06-18 12:54:17 +02002437 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002438 if (direction == kIncomingPacket) {
2439 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2440 if (rtcp.log_time_us() > end_time_us) {
2441 // Only process the first (LOG_START, LOG_END) segment.
2442 break;
2443 }
2444 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2445 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2446 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002447 Alert_RtcpLogTimeGap(direction,
2448 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002449 duration / 1000);
2450 }
2451 last_rtcp_time.emplace(rtcp.log_time_us());
2452 }
2453 } else {
2454 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2455 if (rtcp.log_time_us() > end_time_us) {
2456 // Only process the first (LOG_START, LOG_END) segment.
2457 break;
2458 }
2459 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2460 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2461 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002462 Alert_RtcpLogTimeGap(direction,
2463 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002464 duration / 1000);
2465 }
2466 last_rtcp_time.emplace(rtcp.log_time_us());
2467 }
2468 }
2469}
2470
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002471// TODO(terelius): Notifications could possibly be generated by the same code
2472// that produces the graphs. There is some code duplication that could be
2473// avoided, but that might be solved anyway when we move functionality from the
2474// analyzer to the parser.
2475void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002476 CreateStreamGapAlerts(kIncomingPacket);
2477 CreateStreamGapAlerts(kOutgoingPacket);
2478 CreateTransmissionGapAlerts(kIncomingPacket);
2479 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002480
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002481 int64_t end_time_us = log_segments_.empty()
2482 ? std::numeric_limits<int64_t>::max()
2483 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002484
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002485 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002486 // Loss feedback
2487 int64_t total_lost_packets = 0;
2488 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002489 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2490 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002491 // Only process the first (LOG_START, LOG_END) segment.
2492 break;
2493 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002494 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002495 bwe_update.expected_packets;
2496 total_lost_packets += lost_packets;
2497 total_expected_packets += bwe_update.expected_packets;
2498 }
2499 double avg_outgoing_loss =
2500 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002501 if (avg_outgoing_loss > kMaxLossFraction) {
2502 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002503 }
2504}
2505
terelius54ce6802016-07-13 06:44:41 -07002506} // namespace webrtc