blob: 00369e8d92bbf5554b191523279c0168ffa0b36c [file] [log] [blame]
terelius54ce6802016-07-13 06:44:41 -07001/*
2 * Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020011#include "rtc_tools/event_log_visualizer/analyzer.h"
terelius54ce6802016-07-13 06:44:41 -070012
13#include <algorithm>
Oleh Prypin6581f212017-11-16 00:17:05 +010014#include <cmath>
terelius54ce6802016-07-13 06:44:41 -070015#include <limits>
16#include <map>
terelius54ce6802016-07-13 06:44:41 -070017#include <string>
18#include <utility>
19
Karl Wiberg918f50c2018-07-05 11:40:33 +020020#include "absl/memory/memory.h"
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +010021#include "absl/strings/string_view.h"
Artem Titov741daaf2019-03-21 14:37:36 +010022#include "api/function_view.h"
Sebastian Jansson95edb032019-01-17 16:24:12 +010023#include "api/transport/field_trial_based_config.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020024#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020025#include "call/audio_receive_stream.h"
26#include "call/audio_send_stream.h"
27#include "call/call.h"
28#include "call/video_receive_stream.h"
29#include "call/video_send_stream.h"
Elad Alon99a81b62017-09-21 10:25:29 +020030#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020031#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020032#include "modules/audio_coding/neteq/tools/audio_sink.h"
33#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
34#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
35#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
36#include "modules/audio_coding/neteq/tools/neteq_test.h"
37#include "modules/audio_coding/neteq/tools/resample_input_audio_file.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020038#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
39#include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020040#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020041#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020042#include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010043#include "modules/pacing/packet_router.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020044#include "modules/remote_bitrate_estimator/include/bwe_defines.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020045#include "modules/rtp_rtcp/include/rtp_rtcp.h"
46#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020047#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020048#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
49#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
50#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
51#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
52#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
53#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
54#include "modules/rtp_rtcp/source/rtp_utility.h"
55#include "rtc_base/checks.h"
56#include "rtc_base/format_macros.h"
57#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020058#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020059#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020060#include "rtc_base/strings/string_builder.h"
Sebastian Jansson1175ae02019-03-13 08:56:58 +010061#include "rtc_tools/event_log_visualizer/log_simulation.h"
terelius54ce6802016-07-13 06:44:41 -070062
Bjorn Terelius6984ad22017-10-24 12:19:45 +020063#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
64#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
65#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
66
tereliusdc35dcd2016-08-01 12:03:27 -070067namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070068
terelius54ce6802016-07-13 06:44:41 -070069namespace {
70
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080071const int kNumMicrosecsPerSec = 1000000;
72
elad.alonec304f92017-03-08 05:03:53 -080073void SortPacketFeedbackVector(std::vector<PacketFeedback>* vec) {
74 auto pred = [](const PacketFeedback& packet_feedback) {
75 return packet_feedback.arrival_time_ms == PacketFeedback::kNotReceived;
76 };
77 vec->erase(std::remove_if(vec->begin(), vec->end(), pred), vec->end());
78 std::sort(vec->begin(), vec->end(), PacketFeedbackComparator());
79}
80
terelius54ce6802016-07-13 06:44:41 -070081std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020082 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070083 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020084 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070085}
86
87// Checks whether an SSRC is contained in the list of desired SSRCs.
88// Note that an empty SSRC list matches every SSRC.
89bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
90 if (desired_ssrc.size() == 0)
91 return true;
92 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
93 desired_ssrc.end();
94}
95
96double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
97 // The timestamp is a fixed point representation with 6 bits for seconds
98 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080099 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
100 // microseconds.
terelius54ce6802016-07-13 06:44:41 -0700101 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800102 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -0700103 return abs_send_time * kTimestampToMicroSec;
104}
105
106// Computes the difference |later| - |earlier| where |later| and |earlier|
107// are counters that wrap at |modulus|. The difference is chosen to have the
108// least absolute value. For example if |modulus| is 8, then the difference will
109// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
110// be in [-4, 4].
111int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
112 RTC_DCHECK_LE(1, modulus);
113 RTC_DCHECK_LT(later, modulus);
114 RTC_DCHECK_LT(earlier, modulus);
115 int64_t difference =
116 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
117 int64_t max_difference = modulus / 2;
118 int64_t min_difference = max_difference - modulus + 1;
119 if (difference > max_difference) {
120 difference -= modulus;
121 }
122 if (difference < min_difference) {
123 difference += modulus;
124 }
terelius6addf492016-08-23 17:34:07 -0700125 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100126 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
127 << " expected to be in the range ("
128 << min_difference / 2 << "," << max_difference / 2
129 << ") but is " << difference
130 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700131 }
terelius54ce6802016-07-13 06:44:41 -0700132 return difference;
133}
134
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200135// This is much more reliable for outgoing streams than for incoming streams.
136template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200137absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200138 const RtpPacketContainer& packets,
139 int64_t end_time_us) {
140 RTC_CHECK(packets.size() >= 2);
141 SeqNumUnwrapper<uint32_t> unwrapper;
Philip Eliasson1f850a62019-03-19 12:15:00 +0000142 int64_t first_rtp_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200143 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
144 int64_t first_log_timestamp = packets[0].log_time_us();
Philip Eliasson1f850a62019-03-19 12:15:00 +0000145 int64_t last_rtp_timestamp = first_rtp_timestamp;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200146 int64_t last_log_timestamp = first_log_timestamp;
147 for (size_t i = 1; i < packets.size(); i++) {
148 if (packets[i].log_time_us() > end_time_us)
149 break;
150 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
151 last_log_timestamp = packets[i].log_time_us();
152 }
153 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
154 RTC_LOG(LS_WARNING)
155 << "Failed to estimate RTP clock frequency: Stream too short. ("
156 << packets.size() << " packets, "
157 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200158 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200159 }
160 double duration =
161 static_cast<double>(last_log_timestamp - first_log_timestamp) /
162 kNumMicrosecsPerSec;
163 double estimated_frequency =
164 (last_rtp_timestamp - first_rtp_timestamp) / duration;
165 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
166 if (std::fabs(estimated_frequency - f) < 0.05 * f) {
167 return f;
168 }
169 }
170 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
171 << estimated_frequency
172 << "not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200173 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700174}
175
tereliusdc35dcd2016-08-01 12:03:27 -0700176constexpr float kLeftMargin = 0.01f;
177constexpr float kRightMargin = 0.02f;
178constexpr float kBottomMargin = 0.02f;
179constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700180
Danil Chapovalov431abd92018-06-18 12:54:17 +0200181absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100182 const LoggedRtpPacketIncoming& old_packet,
183 const LoggedRtpPacketIncoming& new_packet) {
184 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
185 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700186 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100187 new_packet.rtp.header.extension.absoluteSendTime,
188 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200189 int64_t recv_time_diff =
190 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700191 double delay_change_us =
192 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100193 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700194 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200195 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700196 }
197}
198
Danil Chapovalov431abd92018-06-18 12:54:17 +0200199absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100200 const LoggedRtpPacketIncoming& old_packet,
201 const LoggedRtpPacketIncoming& new_packet,
202 const double sample_rate) {
203 int64_t send_time_diff =
204 WrappingDifference(new_packet.rtp.header.timestamp,
205 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200206 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700207
terelius53dc23c2017-03-13 05:24:05 -0700208 double delay_change =
209 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100210 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700211 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100212 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100213 RTC_LOG(LS_WARNING) << "Old capture time "
214 << old_packet.rtp.header.timestamp << ", received time "
215 << old_packet.log_time_us();
216 RTC_LOG(LS_WARNING) << "New capture time "
217 << new_packet.rtp.header.timestamp << ", received time "
218 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100219 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800220 << static_cast<double>(recv_time_diff) /
221 kNumMicrosecsPerSec
222 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100223 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100224 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100225 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700226 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100227 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700228}
229
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200230// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700231// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200232template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200233void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200234 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200235 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200236 TimeSeries* result) {
237 for (size_t i = 0; i < data_view.size(); i++) {
238 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200239 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200240 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700241 if (y)
242 result->points.emplace_back(x, *y);
243 }
244}
245
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200246// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700247// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
248// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200249template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700250void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200251 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200252 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
253 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200254 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700255 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700256 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200257 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200258 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700259 if (y)
260 result->points.emplace_back(x, static_cast<float>(*y));
261 }
262}
263
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200264// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700265// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
266// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200267template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700268void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200269 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200270 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
271 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200272 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700273 TimeSeries* result) {
274 ResultType sum = 0;
275 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200276 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200277 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100278 if (y) {
terelius53dc23c2017-03-13 05:24:05 -0700279 sum += *y;
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100280 result->points.emplace_back(x, static_cast<float>(sum));
281 }
tereliusccbbf8d2016-08-10 07:34:28 -0700282 }
283}
284
terelius6addf492016-08-23 17:34:07 -0700285// Calculates a moving average of |data| and stores the result in a TimeSeries.
286// A data point is generated every |step| microseconds from |begin_time|
287// to |end_time|. The value of each data point is the average of the data
288// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200289template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700290void MovingAverage(
Danil Chapovalov431abd92018-06-18 12:54:17 +0200291 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200292 const IterableType& data_view,
Bjorn Terelius068fc352019-02-13 22:38:25 +0100293 AnalyzerConfig config,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200294 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700295 size_t window_index_begin = 0;
296 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700297 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700298
Bjorn Terelius068fc352019-02-13 22:38:25 +0100299 for (int64_t t = config.begin_time_; t < config.end_time_ + config.step_;
300 t += config.step_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200301 while (window_index_end < data_view.size() &&
302 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200303 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700304 if (value)
305 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700306 ++window_index_end;
307 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200308 while (window_index_begin < data_view.size() &&
309 data_view[window_index_begin].log_time_us() <
Bjorn Terelius068fc352019-02-13 22:38:25 +0100310 t - config.window_duration_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200311 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700312 if (value)
313 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700314 ++window_index_begin;
315 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800316 float window_duration_s =
Bjorn Terelius068fc352019-02-13 22:38:25 +0100317 static_cast<float>(config.window_duration_) / kNumMicrosecsPerSec;
318 float x = config.GetCallTimeSec(t);
terelius53dc23c2017-03-13 05:24:05 -0700319 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700320 result->points.emplace_back(x, y);
321 }
322}
323
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100324template <typename T>
325TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
326 AnalyzerConfig config,
327 std::string rtcp_name,
328 int category_id) {
329 TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
330 for (const auto& rtcp : rtcp_list) {
331 float x = config.GetCallTimeSec(rtcp.log_time_us());
332 float y = category_id;
333 time_series.points.emplace_back(x, y);
334 }
335 return time_series;
336}
337
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800338const char kUnknownEnumValue[] = "unknown";
339
340const char kIceCandidateTypeLocal[] = "local";
341const char kIceCandidateTypeStun[] = "stun";
342const char kIceCandidateTypePrflx[] = "prflx";
343const char kIceCandidateTypeRelay[] = "relay";
344
345const char kProtocolUdp[] = "udp";
346const char kProtocolTcp[] = "tcp";
347const char kProtocolSsltcp[] = "ssltcp";
348const char kProtocolTls[] = "tls";
349
350const char kAddressFamilyIpv4[] = "ipv4";
351const char kAddressFamilyIpv6[] = "ipv6";
352
353const char kNetworkTypeEthernet[] = "ethernet";
354const char kNetworkTypeLoopback[] = "loopback";
355const char kNetworkTypeWifi[] = "wifi";
356const char kNetworkTypeVpn[] = "vpn";
357const char kNetworkTypeCellular[] = "cellular";
358
359std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
360 switch (type) {
361 case webrtc::IceCandidateType::kLocal:
362 return kIceCandidateTypeLocal;
363 case webrtc::IceCandidateType::kStun:
364 return kIceCandidateTypeStun;
365 case webrtc::IceCandidateType::kPrflx:
366 return kIceCandidateTypePrflx;
367 case webrtc::IceCandidateType::kRelay:
368 return kIceCandidateTypeRelay;
369 default:
370 return kUnknownEnumValue;
371 }
372}
373
374std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
375 switch (protocol) {
376 case webrtc::IceCandidatePairProtocol::kUdp:
377 return kProtocolUdp;
378 case webrtc::IceCandidatePairProtocol::kTcp:
379 return kProtocolTcp;
380 case webrtc::IceCandidatePairProtocol::kSsltcp:
381 return kProtocolSsltcp;
382 case webrtc::IceCandidatePairProtocol::kTls:
383 return kProtocolTls;
384 default:
385 return kUnknownEnumValue;
386 }
387}
388
389std::string GetAddressFamilyAsString(
390 webrtc::IceCandidatePairAddressFamily family) {
391 switch (family) {
392 case webrtc::IceCandidatePairAddressFamily::kIpv4:
393 return kAddressFamilyIpv4;
394 case webrtc::IceCandidatePairAddressFamily::kIpv6:
395 return kAddressFamilyIpv6;
396 default:
397 return kUnknownEnumValue;
398 }
399}
400
401std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
402 switch (type) {
403 case webrtc::IceCandidateNetworkType::kEthernet:
404 return kNetworkTypeEthernet;
405 case webrtc::IceCandidateNetworkType::kLoopback:
406 return kNetworkTypeLoopback;
407 case webrtc::IceCandidateNetworkType::kWifi:
408 return kNetworkTypeWifi;
409 case webrtc::IceCandidateNetworkType::kVpn:
410 return kNetworkTypeVpn;
411 case webrtc::IceCandidateNetworkType::kCellular:
412 return kNetworkTypeCellular;
413 default:
414 return kUnknownEnumValue;
415 }
416}
417
418std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200419 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800420 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
421 // represents a pair of a local server-reflexive candidate on a WiFi network
422 // and a remote relay candidate using TCP as the relay protocol on a cell
423 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200424 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800425 std::string local_candidate_type =
426 GetIceCandidateTypeAsString(config.local_candidate_type);
427 std::string remote_candidate_type =
428 GetIceCandidateTypeAsString(config.remote_candidate_type);
429 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
430 local_candidate_type +=
431 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
432 }
433 ss << local_candidate_type << ":"
434 << GetNetworkTypeAsString(config.local_network_type) << ":"
435 << GetAddressFamilyAsString(config.local_address_family) << "->"
436 << remote_candidate_type << ":"
437 << GetAddressFamilyAsString(config.remote_address_family) << "@"
438 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200439 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800440}
441
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200442std::string GetDirectionAsString(PacketDirection direction) {
443 if (direction == kIncomingPacket) {
444 return "Incoming";
445 } else {
446 return "Outgoing";
447 }
448}
449
450std::string GetDirectionAsShortString(PacketDirection direction) {
451 if (direction == kIncomingPacket) {
452 return "In";
453 } else {
454 return "Out";
455 }
456}
457
terelius54ce6802016-07-13 06:44:41 -0700458} // namespace
459
Sebastian Janssonb290a6d2019-01-03 14:46:23 +0100460EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200461 bool normalize_time)
Bjorn Terelius068fc352019-02-13 22:38:25 +0100462 : parsed_log_(log) {
463 config_.window_duration_ = 250000;
464 config_.step_ = 10000;
465 config_.normalize_time_ = normalize_time;
466 config_.begin_time_ = parsed_log_.first_timestamp();
467 config_.end_time_ = parsed_log_.last_timestamp();
468 if (config_.end_time_ < config_.begin_time_) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200469 RTC_LOG(LS_WARNING) << "No useful events in the log.";
Bjorn Terelius068fc352019-02-13 22:38:25 +0100470 config_.begin_time_ = config_.end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000471 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200472
473 const auto& log_start_events = parsed_log_.start_log_events();
474 const auto& log_end_events = parsed_log_.stop_log_events();
475 auto start_iter = log_start_events.begin();
476 auto end_iter = log_end_events.begin();
477 while (start_iter != log_start_events.end()) {
478 int64_t start = start_iter->log_time_us();
479 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200480 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200481 if (start_iter != log_start_events.end())
482 next_start.emplace(start_iter->log_time_us());
483 if (end_iter != log_end_events.end() &&
484 end_iter->log_time_us() <=
485 next_start.value_or(std::numeric_limits<int64_t>::max())) {
486 int64_t end = end_iter->log_time_us();
487 RTC_DCHECK_LE(start, end);
488 log_segments_.push_back(std::make_pair(start, end));
489 ++end_iter;
490 } else {
491 // we're missing an end event. Assume that it occurred just before the
492 // next start.
493 log_segments_.push_back(
Bjorn Terelius068fc352019-02-13 22:38:25 +0100494 std::make_pair(start, next_start.value_or(config_.end_time_)));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200495 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700496 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100497 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200498 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700499}
500
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200501class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200502 public:
503 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
504
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200505 void Update(NetworkControlUpdate update) {
506 if (update.target_rate) {
507 last_bitrate_bps_ = update.target_rate->target_rate.bps();
508 bitrate_updated_ = true;
509 }
Stefan Holmer13181032016-07-29 14:48:54 +0200510 }
511
512 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
513 uint32_t bitrate) override {}
514
515 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
516 bool GetAndResetBitrateUpdated() {
517 bool bitrate_updated = bitrate_updated_;
518 bitrate_updated_ = false;
519 return bitrate_updated;
520 }
521
522 private:
523 uint32_t last_bitrate_bps_;
524 bool bitrate_updated_;
525};
526
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200527void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700528 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200529 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
530 // Filter on SSRC.
531 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700532 continue;
terelius54ce6802016-07-13 06:44:41 -0700533 }
terelius54ce6802016-07-13 06:44:41 -0700534
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200535 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
536 LineStyle::kBar);
537 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200538 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200539 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200540 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100541 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200542 };
543 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
544 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700545 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700546 }
547
Bjorn Terelius068fc352019-02-13 22:38:25 +0100548 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
549 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700550 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
551 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200552 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700553}
554
Bjorn Terelius7c974e62019-02-15 17:20:12 +0100555void EventLogAnalyzer::CreateRtcpTypeGraph(PacketDirection direction,
556 Plot* plot) {
557 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
558 parsed_log_.transport_feedbacks(direction), config_, "TWCC", 1));
559 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
560 parsed_log_.receiver_reports(direction), config_, "RR", 2));
561 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
562 parsed_log_.sender_reports(direction), config_, "SR", 3));
563 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
564 parsed_log_.extended_reports(direction), config_, "XR", 4));
565 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.nacks(direction),
566 config_, "NACK", 5));
567 plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.rembs(direction),
568 config_, "REMB", 6));
569 plot->AppendTimeSeries(
570 CreateRtcpTypeTimeSeries(parsed_log_.firs(direction), config_, "FIR", 7));
571 plot->AppendTimeSeries(
572 CreateRtcpTypeTimeSeries(parsed_log_.plis(direction), config_, "PLI", 8));
573 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
574 "Time (s)", kLeftMargin, kRightMargin);
575 plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
576 plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
577}
578
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200579template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700580void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700581 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200582 const IterableType& packets,
583 const std::string& label) {
584 TimeSeries time_series(label, LineStyle::kStep);
585 for (size_t i = 0; i < packets.size(); i++) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100586 float x = config_.GetCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200587 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700588 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200589 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700590}
591
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200592void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
593 Plot* plot) {
594 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
595 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
596 continue;
597 std::string label =
598 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
599 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
600 }
601 std::string label =
602 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
603 if (direction == kIncomingPacket) {
604 CreateAccumulatedPacketsTimeSeries(
605 plot, parsed_log_.incoming_rtcp_packets(), label);
606 } else {
607 CreateAccumulatedPacketsTimeSeries(
608 plot, parsed_log_.outgoing_rtcp_packets(), label);
609 }
philipelccd74892016-09-05 02:46:25 -0700610
Bjorn Terelius068fc352019-02-13 22:38:25 +0100611 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
612 "Time (s)", kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700613 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200614 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
615 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700616}
617
terelius54ce6802016-07-13 06:44:41 -0700618// For each SSRC, plot the time between the consecutive playouts.
619void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200620 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
621 uint32_t ssrc = playout_stream.first;
622 if (!MatchingSsrc(ssrc, desired_ssrc_))
623 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200624 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200625 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200626 for (const auto& playout_event : playout_stream.second) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100627 float x = config_.GetCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200628 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200629 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200630 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200631 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200632 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700633 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200634 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700635 }
636
Bjorn Terelius068fc352019-02-13 22:38:25 +0100637 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
638 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700639 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
640 kTopMargin);
641 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700642}
643
ivocaac9d6f2016-09-22 07:01:47 -0700644// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200645void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
646 Plot* plot) {
647 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
648 if (!IsAudioSsrc(direction, stream.ssrc))
649 continue;
650 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
651 LineStyle::kLine);
652 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700653 if (packet.header.extension.hasAudioLevel) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100654 float x = config_.GetCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700655 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
656 // Here we convert it to dBov.
657 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200658 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700659 }
660 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200661 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700662 }
663
Bjorn Terelius068fc352019-02-13 22:38:25 +0100664 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
665 "Time (s)", kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200666 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200667 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700668}
669
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100670// For each SSRC, plot the sequence number difference between consecutive
671// incoming packets.
terelius54ce6802016-07-13 06:44:41 -0700672void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200673 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
674 // Filter on SSRC.
675 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700676 continue;
terelius54ce6802016-07-13 06:44:41 -0700677 }
terelius54ce6802016-07-13 06:44:41 -0700678
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200679 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
680 LineStyle::kBar);
681 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
682 const LoggedRtpPacketIncoming& new_packet) {
683 int64_t diff =
684 WrappingDifference(new_packet.rtp.header.sequenceNumber,
685 old_packet.rtp.header.sequenceNumber, 1ul << 16);
686 return diff;
687 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200688 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100689 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200690 };
691 ProcessPairs<LoggedRtpPacketIncoming, float>(
692 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
693 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700694 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700695 }
696
Bjorn Terelius068fc352019-02-13 22:38:25 +0100697 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
698 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700699 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
700 kTopMargin);
Konrad Hofbauerca3c8012019-02-15 20:52:19 +0100701 plot->SetTitle("Incoming sequence number delta");
terelius54ce6802016-07-13 06:44:41 -0700702}
703
Stefan Holmer99f8e082016-09-09 13:37:50 +0200704void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200705 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
706 const std::vector<LoggedRtpPacketIncoming>& packets =
707 stream.incoming_packets;
708 // Filter on SSRC.
709 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200710 continue;
711 }
712
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200713 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
714 LineStyle::kLine, PointStyle::kHighlight);
715 // TODO(terelius): Should the window and step size be read from the class
716 // instead?
717 const int64_t kWindowUs = 1000000;
718 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100719 SeqNumUnwrapper<uint16_t> unwrapper_;
720 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800721 size_t window_index_begin = 0;
722 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200723 uint64_t highest_seq_number =
724 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
725 uint64_t highest_prior_seq_number =
726 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800727
Bjorn Terelius068fc352019-02-13 22:38:25 +0100728 for (int64_t t = config_.begin_time_; t < config_.end_time_ + kStep;
729 t += kStep) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200730 while (window_index_end < packets.size() &&
731 packets[window_index_end].rtp.log_time_us() < t) {
732 uint64_t sequence_number = unwrapper_.Unwrap(
733 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800734 highest_seq_number = std::max(highest_seq_number, sequence_number);
735 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200736 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200737 while (window_index_begin < packets.size() &&
738 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
739 uint64_t sequence_number = prior_unwrapper_.Unwrap(
740 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800741 highest_prior_seq_number =
742 std::max(highest_prior_seq_number, sequence_number);
743 ++window_index_begin;
744 }
Bjorn Terelius068fc352019-02-13 22:38:25 +0100745 float x = config_.GetCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200746 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800747 if (expected_packets > 0) {
748 int64_t received_packets = window_index_end - window_index_begin;
749 int64_t lost_packets = expected_packets - received_packets;
750 float y = static_cast<float>(lost_packets) / expected_packets * 100;
751 time_series.points.emplace_back(x, y);
752 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200753 }
philipel35ba9bd2017-04-19 05:58:51 -0700754 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200755 }
756
Bjorn Terelius068fc352019-02-13 22:38:25 +0100757 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
758 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100759 plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
760 plot->SetTitle("Incoming packet loss (derived from incoming packets)");
Stefan Holmer99f8e082016-09-09 13:37:50 +0200761}
762
terelius2ee076d2017-08-15 02:04:02 -0700763void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100764 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200765 // Filter on SSRC.
766 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200767 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700768 continue;
769 }
terelius54ce6802016-07-13 06:44:41 -0700770
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100771 const std::vector<LoggedRtpPacketIncoming>& packets =
772 stream.incoming_packets;
773 if (packets.size() < 100) {
774 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
775 << packets.size() << " packets in the stream.";
776 continue;
777 }
778 int64_t end_time_us = log_segments_.empty()
779 ? std::numeric_limits<int64_t>::max()
780 : log_segments_.front().second;
781 absl::optional<uint32_t> estimated_frequency =
782 EstimateRtpClockFrequency(packets, end_time_us);
783 if (!estimated_frequency)
784 continue;
785 const double frequency_hz = *estimated_frequency;
786 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
787 RTC_LOG(LS_WARNING)
788 << "Video stream should use a 90 kHz clock but appears to use "
789 << frequency_hz / 1000 << ". Discarding.";
790 continue;
791 }
792
793 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100794 return this->config_.GetCallTimeSec(packet.log_time_us());
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100795 };
796 auto ToNetworkDelay = [frequency_hz](
797 const LoggedRtpPacketIncoming& old_packet,
798 const LoggedRtpPacketIncoming& new_packet) {
799 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
800 };
801
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200802 TimeSeries capture_time_data(
803 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
804 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100805 AccumulatePairs<LoggedRtpPacketIncoming, double>(
806 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700807 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700808
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200809 TimeSeries send_time_data(
810 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
811 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100812 AccumulatePairs<LoggedRtpPacketIncoming, double>(
813 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
814 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700815 }
816
Bjorn Terelius068fc352019-02-13 22:38:25 +0100817 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
818 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +0100819 plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
820 plot->SetTitle("Incoming network delay (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700821}
822
tereliusf736d232016-08-04 10:00:11 -0700823// Plot the fraction of packets lost (as perceived by the loss-based BWE).
824void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100825 TimeSeries time_series("Fraction lost", LineStyle::kLine,
826 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200827 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100828 float x = config_.GetCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200829 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700830 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700831 }
tereliusf736d232016-08-04 10:00:11 -0700832
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200833 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +0100834 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
835 "Time (s)", kLeftMargin, kRightMargin);
Konrad Hofbauerd036c652019-02-14 16:17:28 +0100836 plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
837 plot->SetTitle("Outgoing packet loss (as reported by BWE)");
tereliusf736d232016-08-04 10:00:11 -0700838}
839
terelius54ce6802016-07-13 06:44:41 -0700840// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200841void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
842 // TODO(terelius): This could be provided by the parser.
843 std::multimap<int64_t, size_t> packets_in_order;
844 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
845 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
846 packets_in_order.insert(
847 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700848 }
849
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200850 auto window_begin = packets_in_order.begin();
851 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700852 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700853
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800854 if (!packets_in_order.empty()) {
855 // Calculate a moving average of the bitrate and store in a TimeSeries.
856 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
857 for (int64_t time = config_.begin_time_;
858 time < config_.end_time_ + config_.step_; time += config_.step_) {
859 while (window_end != packets_in_order.end() && window_end->first < time) {
860 bytes_in_window += window_end->second;
861 ++window_end;
862 }
863 while (window_begin != packets_in_order.end() &&
864 window_begin->first < time - config_.window_duration_) {
865 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
866 bytes_in_window -= window_begin->second;
867 ++window_begin;
868 }
869 float window_duration_in_seconds =
870 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
871 float x = config_.GetCallTimeSec(time);
872 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
873 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700874 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800875 plot->AppendTimeSeries(std::move(bitrate_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200876 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200877
878 // Overlay the outgoing REMB over incoming bitrate.
879 TimeSeries remb_series("Remb", LineStyle::kStep);
880 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100881 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200882 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
883 remb_series.points.emplace_back(x, y);
884 }
885 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
886
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800887 if (!parsed_log_.generic_packets_received().empty()) {
888 TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
889 auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
890 return packet.packet_length * 8.0 / 1000.0;
891 };
892 MovingAverage<LoggedGenericPacketReceived, double>(
893 GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
894 &time_series);
895 plot->AppendTimeSeries(std::move(time_series));
896 }
897
Bjorn Terelius068fc352019-02-13 22:38:25 +0100898 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
899 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200900 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
901 plot->SetTitle("Incoming RTP bitrate");
902}
903
904// Plot the total bandwidth used by all RTP streams.
905void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
906 bool show_detector_state,
907 bool show_alr_state) {
908 // TODO(terelius): This could be provided by the parser.
909 std::multimap<int64_t, size_t> packets_in_order;
910 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
911 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
912 packets_in_order.insert(
913 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
914 }
915
916 auto window_begin = packets_in_order.begin();
917 auto window_end = packets_in_order.begin();
918 size_t bytes_in_window = 0;
919
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800920 if (!packets_in_order.empty()) {
921 // Calculate a moving average of the bitrate and store in a TimeSeries.
922 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
923 for (int64_t time = config_.begin_time_;
924 time < config_.end_time_ + config_.step_; time += config_.step_) {
925 while (window_end != packets_in_order.end() && window_end->first < time) {
926 bytes_in_window += window_end->second;
927 ++window_end;
928 }
929 while (window_begin != packets_in_order.end() &&
930 window_begin->first < time - config_.window_duration_) {
931 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
932 bytes_in_window -= window_begin->second;
933 ++window_begin;
934 }
935 float window_duration_in_seconds =
936 static_cast<float>(config_.window_duration_) / kNumMicrosecsPerSec;
937 float x = config_.GetCallTimeSec(time);
938 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
939 bitrate_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200940 }
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -0800941 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700942 }
943
terelius8058e582016-07-25 01:32:41 -0700944 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200945 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
946 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100947 float x = config_.GetCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200948 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
949 loss_series.points.emplace_back(x, y);
950 }
philipel10fc0e62017-04-11 01:50:23 -0700951
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200952 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
953 IntervalSeries overusing_series("Overusing", "#ff8e82",
954 IntervalSeries::kHorizontal);
955 IntervalSeries underusing_series("Underusing", "#5092fc",
956 IntervalSeries::kHorizontal);
957 IntervalSeries normal_series("Normal", "#c4ffc4",
958 IntervalSeries::kHorizontal);
959 IntervalSeries* last_series = &normal_series;
960 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700961
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200962 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700963
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200964 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100965 float x = config_.GetCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200966 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700967
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200968 if (last_detector_state != delay_update.detector_state) {
969 last_series->intervals.emplace_back(last_detector_switch, x);
970 last_detector_state = delay_update.detector_state;
971 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700972
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200973 switch (delay_update.detector_state) {
974 case BandwidthUsage::kBwNormal:
975 last_series = &normal_series;
976 break;
977 case BandwidthUsage::kBwUnderusing:
978 last_series = &underusing_series;
979 break;
980 case BandwidthUsage::kBwOverusing:
981 last_series = &overusing_series;
982 break;
983 case BandwidthUsage::kLast:
984 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200985 }
986 }
philipel23c7f252017-07-14 06:30:03 -0700987
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200988 delay_series.points.emplace_back(x, y);
989 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200990
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200991 RTC_CHECK(last_series);
Bjorn Terelius068fc352019-02-13 22:38:25 +0100992 last_series->intervals.emplace_back(last_detector_switch, config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200993
994 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
995 PointStyle::kHighlight);
996 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +0100997 float x = config_.GetCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200998 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
999 created_series.points.emplace_back(x, y);
1000 }
1001
1002 TimeSeries result_series("Probing results.", LineStyle::kNone,
1003 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001004 for (auto& result : parsed_log_.bwe_probe_success_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001005 float x = config_.GetCallTimeSec(result.log_time_us());
Bjorn Terelius7a0bb002018-05-29 14:45:53 +02001006 float y = static_cast<float>(result.bitrate_bps) / 1000;
1007 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001008 }
1009
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001010 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1011 PointStyle::kHighlight);
1012 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001013 float x = config_.GetCallTimeSec(failure.log_time_us());
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001014 probe_failures_series.points.emplace_back(x, 0);
1015 }
1016
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001017 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1018 bool previously_in_alr = false;
1019 int64_t alr_start = 0;
1020 for (auto& alr : parsed_log_.alr_state_events()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001021 float y = config_.GetCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001022 if (!previously_in_alr && alr.in_alr) {
1023 alr_start = alr.log_time_us();
1024 previously_in_alr = true;
1025 } else if (previously_in_alr && !alr.in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001026 float x = config_.GetCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +01001027 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001028 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +00001029 }
Björn Tereliusff612732018-04-25 14:23:01 +00001030 }
1031
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001032 if (previously_in_alr) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001033 float x = config_.GetCallTimeSec(alr_start);
1034 float y = config_.GetCallTimeSec(config_.end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001035 alr_state.intervals.emplace_back(x, y);
1036 }
1037
1038 if (show_detector_state) {
1039 plot->AppendIntervalSeries(std::move(overusing_series));
1040 plot->AppendIntervalSeries(std::move(underusing_series));
1041 plot->AppendIntervalSeries(std::move(normal_series));
1042 }
1043
1044 if (show_alr_state) {
1045 plot->AppendIntervalSeries(std::move(alr_state));
1046 }
1047 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001048 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001049 plot->AppendTimeSeries(std::move(delay_series));
1050 plot->AppendTimeSeries(std::move(created_series));
1051 plot->AppendTimeSeries(std::move(result_series));
1052
1053 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001054 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001055 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001056 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001057 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001058 remb_series.points.emplace_back(x, y);
1059 }
1060 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1061
Piotr (Peter) Slatalacf8405e2019-02-14 13:44:57 -08001062 if (!parsed_log_.generic_packets_sent().empty()) {
1063 {
1064 TimeSeries time_series("Outgoing generic total bitrate",
1065 LineStyle::kLine);
1066 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1067 return packet.packet_length() * 8.0 / 1000.0;
1068 };
1069 MovingAverage<LoggedGenericPacketSent, double>(
1070 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1071 &time_series);
1072 plot->AppendTimeSeries(std::move(time_series));
1073 }
1074
1075 {
1076 TimeSeries time_series("Outgoing generic payload bitrate",
1077 LineStyle::kLine);
1078 auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1079 return packet.payload_length * 8.0 / 1000.0;
1080 };
1081 MovingAverage<LoggedGenericPacketSent, double>(
1082 GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1083 &time_series);
1084 plot->AppendTimeSeries(std::move(time_series));
1085 }
1086 }
1087
Bjorn Terelius068fc352019-02-13 22:38:25 +01001088 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1089 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001090 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001091 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001092}
1093
1094// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001095void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1096 Plot* plot) {
1097 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1098 // Filter on SSRC.
1099 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001100 continue;
terelius54ce6802016-07-13 06:44:41 -07001101 }
1102
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001103 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1104 LineStyle::kLine);
1105 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1106 return packet.total_length * 8.0 / 1000.0;
1107 };
terelius53dc23c2017-03-13 05:24:05 -07001108 MovingAverage<LoggedRtpPacket, double>(
Bjorn Terelius068fc352019-02-13 22:38:25 +01001109 GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001110 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001111 }
1112
Bjorn Terelius068fc352019-02-13 22:38:25 +01001113 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1114 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001115 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001116 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001117}
1118
Bjorn Terelius9775a582019-02-15 17:29:58 +01001119// Plot the bitrate allocation for each temporal and spatial layer.
1120// Computed from RTCP XR target bitrate block, so the graph is only populated if
1121// those are sent.
1122void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1123 Plot* plot) {
1124 std::map<LayerDescription, TimeSeries> time_series;
1125 const auto& xr_list = parsed_log_.extended_reports(direction);
1126 for (const auto& rtcp : xr_list) {
1127 const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1128 rtcp.xr.target_bitrate();
1129 if (!target_bitrate.has_value())
1130 continue;
1131 for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1132 LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1133 bitrate_item.temporal_layer);
1134 auto time_series_it = time_series.find(layer);
1135 if (time_series_it == time_series.end()) {
1136 std::string layer_name = GetLayerName(layer);
1137 bool inserted;
1138 std::tie(time_series_it, inserted) = time_series.insert(
1139 std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1140 RTC_DCHECK(inserted);
1141 }
1142 float x = config_.GetCallTimeSec(rtcp.log_time_us());
1143 float y = bitrate_item.target_bitrate_kbps;
1144 time_series_it->second.points.emplace_back(x, y);
1145 }
1146 }
1147 for (auto& layer : time_series) {
1148 plot->AppendTimeSeries(std::move(layer.second));
1149 }
1150 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1151 "Time (s)", kLeftMargin, kRightMargin);
1152 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1153 if (direction == kIncomingPacket)
1154 plot->SetTitle("Target bitrate per incoming layer");
1155 else
1156 plot->SetTitle("Target bitrate per outgoing layer");
1157}
1158
Sebastian Jansson1175ae02019-03-13 08:56:58 +01001159void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1160 TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1161 PointStyle::kHighlight);
1162 TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1163 PointStyle::kHighlight);
1164 TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1165 PointStyle::kHighlight);
1166 TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1167 PointStyle::kHighlight);
1168
1169 RtcEventLogNullImpl null_event_log;
1170 LogBasedNetworkControllerSimulation simulation(
1171 absl::make_unique<GoogCcNetworkControllerFactory>(&null_event_log),
1172 [&](const NetworkControlUpdate& update, Timestamp at_time) {
1173 if (update.target_rate) {
1174 target_rates.points.emplace_back(
1175 config_.GetCallTimeSec(at_time.us()),
1176 update.target_rate->target_rate.kbps<float>());
1177 }
1178 });
1179
1180 simulation.ProcessEventsInLog(parsed_log_);
1181 for (const auto& logged : parsed_log_.bwe_delay_updates())
1182 delay_based.points.emplace_back(
1183 config_.GetCallTimeSec(logged.log_time_us()),
1184 logged.bitrate_bps / 1000);
1185 for (const auto& logged : parsed_log_.bwe_probe_success_events())
1186 probe_results.points.emplace_back(
1187 config_.GetCallTimeSec(logged.log_time_us()),
1188 logged.bitrate_bps / 1000);
1189 for (const auto& logged : parsed_log_.bwe_loss_updates())
1190 loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time_us()),
1191 logged.bitrate_bps / 1000);
1192
1193 plot->AppendTimeSeries(std::move(delay_based));
1194 plot->AppendTimeSeries(std::move(loss_based));
1195 plot->AppendTimeSeries(std::move(probe_results));
1196 plot->AppendTimeSeries(std::move(target_rates));
1197
1198 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1199 "Time (s)", kLeftMargin, kRightMargin);
1200 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1201 plot->SetTitle("Simulated BWE behavior");
1202}
1203
Bjorn Terelius28db2662017-10-04 14:22:43 +02001204void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001205 using RtpPacketType = LoggedRtpPacketOutgoing;
1206 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001207
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001208 // TODO(terelius): This could be provided by the parser.
1209 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1210 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1211 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1212 outgoing_rtp.insert(
1213 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001214 }
1215
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001216 const std::vector<TransportFeedbackType>& incoming_rtcp =
1217 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001218
1219 SimulatedClock clock(0);
1220 BitrateObserver observer;
1221 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001222 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001223 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001224 TransportFeedbackAdapter transport_feedback;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001225 auto factory = GoogCcNetworkControllerFactory(&null_event_log);
1226 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001227 // TODO(holmer): Log the call config and use that here instead.
1228 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001229 NetworkControllerConfig cc_config;
Sebastian Jansson78416b62018-10-18 13:08:17 +02001230 cc_config.constraints.at_time = Timestamp::us(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001231 cc_config.constraints.starting_rate = DataRate::bps(kDefaultStartBitrateBps);
1232 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001233
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001234 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1235 PointStyle::kHighlight);
1236 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1237 PointStyle::kHighlight);
1238 TimeSeries acked_estimate_time_series(
1239 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001240
1241 auto rtp_iterator = outgoing_rtp.begin();
1242 auto rtcp_iterator = incoming_rtcp.begin();
1243
1244 auto NextRtpTime = [&]() {
1245 if (rtp_iterator != outgoing_rtp.end())
1246 return static_cast<int64_t>(rtp_iterator->first);
1247 return std::numeric_limits<int64_t>::max();
1248 };
1249
1250 auto NextRtcpTime = [&]() {
1251 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001252 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001253 return std::numeric_limits<int64_t>::max();
1254 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001255 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001256
1257 auto NextProcessTime = [&]() {
1258 if (rtcp_iterator != incoming_rtcp.end() ||
1259 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001260 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001261 }
1262 return std::numeric_limits<int64_t>::max();
1263 };
1264
Stefan Holmer492ee282016-10-27 17:19:20 +02001265 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001266#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001267 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001268 // The event_log_visualizer should normally not be compiled with
1269 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1270 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1271 // and piping the output to plot_dynamics.py can be used as a hack to get the
1272 // internal state of various BWE components. In this case, it is important
1273 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1274 // SendSideCongestionController since that would lead to duplicate outputs.
1275 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Sebastian Jansson95edb032019-01-17 16:24:12 +01001276 &field_trial_config_,
1277 absl::make_unique<BitrateEstimator>(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001278#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001279 int64_t time_us =
1280 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001281 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001282 while (time_us != std::numeric_limits<int64_t>::max()) {
1283 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001284 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1285 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1286 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1287 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1288 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
Erik Språng30a276b2019-04-23 12:00:11 +02001289 RtpPacketSendInfo packet_info;
1290 packet_info.ssrc = rtp_packet.rtp.header.ssrc;
1291 packet_info.rtp_sequence_number =
1292 rtp_packet.rtp.header.extension.transportSequenceNumber;
1293 packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
1294 packet_info.has_rtp_sequence_number = true;
1295 packet_info.length = rtp_packet.rtp.total_length;
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001296 transport_feedback.AddPacket(
Erik Språng30a276b2019-04-23 12:00:11 +02001297 packet_info,
1298 0u, // Per packet overhead bytes.
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001299 Timestamp::us(rtp_packet.rtp.log_time_us()));
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001300 rtc::SentPacket sent_packet(
1301 rtp_packet.rtp.header.extension.transportSequenceNumber,
1302 rtp_packet.rtp.log_time_us() / 1000);
1303 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1304 if (sent_msg)
1305 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1306 }
1307 ++rtp_iterator;
1308 }
Stefan Holmer13181032016-07-29 14:48:54 +02001309 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001310 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001311
1312 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
Sebastian Jansson05acd2b2019-01-21 13:07:47 +01001313 rtcp_iterator->transport_feedback,
1314 Timestamp::ms(clock.TimeInMilliseconds()));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001315 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001316 if (feedback_msg) {
1317 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
1318 std::vector<PacketFeedback> feedback =
1319 transport_feedback.GetTransportFeedbackVector();
1320 SortPacketFeedbackVector(&feedback);
1321 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001322#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001323 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001324#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001325 for (const PacketFeedback& packet : feedback)
1326 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1327 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
1328 }
Stefan Holmer13181032016-07-29 14:48:54 +02001329 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001330
Bjorn Terelius068fc352019-02-13 22:38:25 +01001331 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001332 float y = bitrate_bps.value_or(0) / 1000;
1333 acked_time_series.points.emplace_back(x, y);
1334#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1335 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1336 acked_estimate_time_series.points.emplace_back(x, y);
1337#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001338 ++rtcp_iterator;
1339 }
stefanc3de0332016-08-02 07:22:17 -07001340 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1341 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001342 ProcessInterval msg;
1343 msg.at_time = Timestamp::us(clock.TimeInMicroseconds());
1344 observer.Update(goog_cc->OnProcessInterval(msg));
1345 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001346 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001347 if (observer.GetAndResetBitrateUpdated() ||
1348 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001349 uint32_t y = observer.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001350 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001351 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001352 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001353 }
1354 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1355 }
1356 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001357 plot->AppendTimeSeries(std::move(time_series));
1358 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001359 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001360
Bjorn Terelius068fc352019-02-13 22:38:25 +01001361 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1362 "Time (s)", kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001363 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001364 plot->SetTitle("Simulated send-side BWE behavior");
1365}
1366
1367void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001368 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001369 class RembInterceptingPacketRouter : public PacketRouter {
1370 public:
1371 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1372 uint32_t bitrate_bps) override {
1373 last_bitrate_bps_ = bitrate_bps;
1374 bitrate_updated_ = true;
1375 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1376 }
1377 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1378 bool GetAndResetBitrateUpdated() {
1379 bool bitrate_updated = bitrate_updated_;
1380 bitrate_updated_ = false;
1381 return bitrate_updated;
1382 }
1383
1384 private:
1385 uint32_t last_bitrate_bps_;
1386 bool bitrate_updated_;
1387 };
1388
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001389 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001390
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001391 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1392 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1393 for (const auto& rtp_packet : stream.incoming_packets)
1394 incoming_rtp.insert(
1395 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001396 }
1397 }
1398
1399 SimulatedClock clock(0);
1400 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001401 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001402 // Is this intentional?
1403 ReceiveSideCongestionController rscc(&clock, &packet_router);
1404 // TODO(holmer): Log the call config and use that here instead.
1405 // static const uint32_t kDefaultStartBitrateBps = 300000;
1406 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1407
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001408 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1409 PointStyle::kHighlight);
1410 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001411
1412 RateStatistics acked_bitrate(250, 8000);
1413 int64_t last_update_us = 0;
1414 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001415 const RtpPacketType& packet = *kv.second;
1416 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1417 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1418 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001419 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001420 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001421 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001422 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001423 if (bitrate_bps) {
1424 uint32_t y = *bitrate_bps / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001425 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001426 acked_time_series.points.emplace_back(x, y);
1427 }
1428 if (packet_router.GetAndResetBitrateUpdated() ||
1429 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1430 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001431 float x = config_.GetCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001432 time_series.points.emplace_back(x, y);
1433 last_update_us = clock.TimeInMicroseconds();
1434 }
1435 }
1436 // Add the data set to the plot.
1437 plot->AppendTimeSeries(std::move(time_series));
1438 plot->AppendTimeSeries(std::move(acked_time_series));
1439
Bjorn Terelius068fc352019-02-13 22:38:25 +01001440 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1441 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001442 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1443 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001444}
1445
tereliuse34c19c2016-08-15 08:47:14 -07001446void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001447 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1448 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001449 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001450 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001451 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1452 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001453
stefana0a8ed72017-09-06 02:06:32 -07001454 int64_t prev_y = 0;
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001455 for (auto packet : GetNetworkTrace(parsed_log_)) {
1456 if (packet.arrival_time_ms == PacketFeedback::kNotReceived)
1457 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001458 float x = config_.GetCallTimeSec(1000 * packet.feedback_arrival_time_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001459 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1460 late_feedback_series.points.emplace_back(x, prev_y);
1461 continue;
stefanc3de0332016-08-02 07:22:17 -07001462 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001463 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1464 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001465 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1466 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1467 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001468 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001469 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001470
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001471 // We assume that the base network delay (w/o queues) is equal to half
1472 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1473 // observed 1-ways delay and add half the minumum RTT.
1474 const int64_t estimated_clock_offset_ms =
1475 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001476 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001477 point.y -= estimated_clock_offset_ms;
stefana0a8ed72017-09-06 02:06:32 -07001478 for (TimeSeriesPoint& point : late_feedback_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001479 point.y -= estimated_clock_offset_ms;
1480
stefanc3de0332016-08-02 07:22:17 -07001481 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001482 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1483 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001484
Bjorn Terelius068fc352019-02-13 22:38:25 +01001485 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1486 "Time (s)", kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001487 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Konrad Hofbauer5be3bbd2019-01-21 12:31:07 +01001488 plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001489}
stefan08383272016-12-20 08:51:52 -08001490
Bjorn Terelius0295a962017-10-25 17:42:41 +02001491void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001492 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1493 const std::vector<LoggedRtpPacketOutgoing>& packets =
1494 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001495
Konrad Hofbauerbfb735b2019-04-16 11:12:11 +02001496 if (IsRtxSsrc(kOutgoingPacket, stream.ssrc)) {
1497 continue;
1498 }
1499
Bjorn Terelius0295a962017-10-25 17:42:41 +02001500 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001501 RTC_LOG(LS_WARNING)
1502 << "Can't estimate a the RTP clock frequency or the "
1503 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001504 continue;
1505 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001506 int64_t end_time_us = log_segments_.empty()
1507 ? std::numeric_limits<int64_t>::max()
1508 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001509 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001510 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001511 if (!estimated_frequency)
1512 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001513 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1514 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001515 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001516 << "Video stream should use a 90 kHz clock but appears to use "
1517 << *estimated_frequency / 1000 << ". Discarding.";
1518 continue;
1519 }
1520
1521 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001522 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001523 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001524 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001525 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1526 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001527 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1528 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1529 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001530 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001531 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001532 first_capture_timestamp) /
1533 *estimated_frequency * 1000;
1534 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001535 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1536 1000;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001537 float x = config_.GetCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001538 float y = send_time_ms - capture_time_ms;
1539 pacer_delay_series.points.emplace_back(x, y);
1540 }
1541 plot->AppendTimeSeries(std::move(pacer_delay_series));
1542 }
1543
Bjorn Terelius068fc352019-02-13 22:38:25 +01001544 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1545 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001546 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1547 plot->SetTitle(
1548 "Delay from capture to send time. (First packet normalized to 0.)");
1549}
1550
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001551void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1552 Plot* plot) {
1553 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1554 TimeSeries rtp_timestamps(
1555 GetStreamName(direction, stream.ssrc) + " capture-time",
1556 LineStyle::kLine, PointStyle::kHighlight);
1557 for (const auto& packet : stream.packet_view) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001558 float x = config_.GetCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001559 float y = packet.header.timestamp;
1560 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001561 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001562 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001563
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001564 TimeSeries rtcp_timestamps(
1565 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1566 LineStyle::kLine, PointStyle::kHighlight);
1567 // TODO(terelius): Why only sender reports?
1568 const auto& sender_reports = parsed_log_.sender_reports(direction);
1569 for (const auto& rtcp : sender_reports) {
1570 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1571 continue;
Bjorn Terelius068fc352019-02-13 22:38:25 +01001572 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001573 float y = rtcp.sr.rtp_timestamp();
1574 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001575 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001576 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001577 }
1578
Bjorn Terelius068fc352019-02-13 22:38:25 +01001579 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1580 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001581 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1582 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001583}
michaelt6e5b2192017-02-22 07:33:27 -08001584
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001585void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1586 PacketDirection direction,
1587 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1588 std::string title,
1589 std::string yaxis_label,
1590 Plot* plot) {
1591 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1592 const auto& sender_reports = parsed_log_.sender_reports(direction);
1593 for (const auto& rtcp : sender_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001594 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001595 uint32_t ssrc = rtcp.sr.sender_ssrc();
1596 for (const auto& block : rtcp.sr.report_blocks()) {
1597 float y = fy(block);
1598 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1599 bool inserted;
1600 if (sr_report_it == sr_reports_by_ssrc.end()) {
1601 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1602 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1603 LineStyle::kLine, PointStyle::kHighlight));
1604 }
1605 sr_report_it->second.points.emplace_back(x, y);
1606 }
1607 }
1608 for (auto& kv : sr_reports_by_ssrc) {
1609 plot->AppendTimeSeries(std::move(kv.second));
1610 }
1611
1612 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1613 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1614 for (const auto& rtcp : receiver_reports) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001615 float x = config_.GetCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001616 uint32_t ssrc = rtcp.rr.sender_ssrc();
1617 for (const auto& block : rtcp.rr.report_blocks()) {
1618 float y = fy(block);
1619 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1620 bool inserted;
1621 if (rr_report_it == rr_reports_by_ssrc.end()) {
1622 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1623 ssrc,
1624 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1625 LineStyle::kLine, PointStyle::kHighlight));
1626 }
1627 rr_report_it->second.points.emplace_back(x, y);
1628 }
1629 }
1630 for (auto& kv : rr_reports_by_ssrc) {
1631 plot->AppendTimeSeries(std::move(kv.second));
1632 }
1633
Bjorn Terelius068fc352019-02-13 22:38:25 +01001634 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1635 "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001636 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1637 plot->SetTitle(title);
1638}
1639
michaelt6e5b2192017-02-22 07:33:27 -08001640void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001641 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1642 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001643 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001644 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001645 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001646 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001647 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001648 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001649 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001650 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001651 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001652 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001653 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001654 ToCallTime, GetAnaBitrateBps,
1655 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001656 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001657 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1658 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001659 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1660 plot->SetTitle("Reported audio encoder target bitrate");
1661}
1662
1663void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001664 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1665 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001666 auto GetAnaFrameLengthMs =
1667 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001668 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001669 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001670 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001671 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001672 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001673 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001674 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001675 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001676 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001677 ToCallTime, GetAnaFrameLengthMs,
1678 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001679 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001680 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1681 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001682 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1683 plot->SetTitle("Reported audio encoder frame length");
1684}
1685
terelius2ee076d2017-08-15 02:04:02 -07001686void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001687 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001688 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001689 auto GetAnaPacketLoss =
1690 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001691 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001692 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001693 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001694 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001695 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001696 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001697 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001698 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001699 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001700 ToCallTime, GetAnaPacketLoss,
1701 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001702 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001703 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1704 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001705 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1706 kTopMargin);
1707 plot->SetTitle("Reported audio encoder lost packets");
1708}
1709
1710void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001711 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1712 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001713 auto GetAnaFecEnabled =
1714 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001715 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001716 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001717 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001718 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001719 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001720 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01001721 return this->config_.GetCallTimeSec(packet.log_time_us());
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001722 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001723 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001724 ToCallTime, GetAnaFecEnabled,
1725 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001726 plot->AppendTimeSeries(std::move(time_series));
Bjorn Terelius068fc352019-02-13 22:38:25 +01001727 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1728 "Time (s)", kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001729 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1730 plot->SetTitle("Reported audio encoder FEC");
1731}
1732
1733void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001734 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1735 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001736 auto GetAnaDtxEnabled =
1737 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001738 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001739 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001740 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001741 return absl::optional<float>();
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, GetAnaDtxEnabled,
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, "DTX (false/true)", kBottomMargin, kTopMargin);
1753 plot->SetTitle("Reported audio encoder DTX");
1754}
1755
1756void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001757 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1758 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001759 auto GetAnaNumChannels =
1760 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001761 if (ana_event.config.num_channels)
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.num_channels));
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, GetAnaNumChannels,
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, "Number of channels (1 (mono)/2 (stereo))",
1776 kBottomMargin, kTopMargin);
1777 plot->SetTitle("Reported audio encoder number of channels");
1778}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001779
1780class NetEqStreamInput : public test::NetEqInput {
1781 public:
1782 // Does not take any ownership, and all pointers must refer to valid objects
1783 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001784 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001785 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001786 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001787 : packet_stream_(*packet_stream),
1788 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001789 output_events_it_(output_events->begin()),
1790 output_events_end_(output_events->end()),
1791 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001792 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001793 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001794 }
1795
Danil Chapovalov431abd92018-06-18 12:54:17 +02001796 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001797 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001798 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001799 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001800 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001801 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001802 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001803 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001804 }
1805
Danil Chapovalov431abd92018-06-18 12:54:17 +02001806 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001807 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001808 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001809 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001810 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001811 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001812 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001813 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001814 }
1815
1816 std::unique_ptr<PacketData> PopPacket() override {
1817 if (packet_stream_it_ == packet_stream_.end()) {
1818 return std::unique_ptr<PacketData>();
1819 }
1820 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001821 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001822 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001823
1824 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1825 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001826 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1827 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001828 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1829
1830 ++packet_stream_it_;
1831 return packet_data;
1832 }
1833
1834 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001835 if (output_events_it_ != output_events_end_) {
1836 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001837 }
1838 }
1839
1840 bool ended() const override { return !NextEventTime(); }
1841
Danil Chapovalov431abd92018-06-18 12:54:17 +02001842 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001843 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001844 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001845 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001846 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001847 }
1848
1849 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001850 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1851 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001852 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1853 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001854 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001855};
1856
1857namespace {
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001858
1859// Factory to create a "replacement decoder" that produces the decoded audio
1860// by reading from a file rather than from the encoded payloads.
1861class ReplacementAudioDecoderFactory : public AudioDecoderFactory {
1862 public:
1863 ReplacementAudioDecoderFactory(const absl::string_view replacement_file_name,
1864 int file_sample_rate_hz)
1865 : replacement_file_name_(replacement_file_name),
1866 file_sample_rate_hz_(file_sample_rate_hz) {}
1867
1868 std::vector<AudioCodecSpec> GetSupportedDecoders() override {
1869 RTC_NOTREACHED();
1870 return {};
1871 }
1872
1873 bool IsSupportedDecoder(const SdpAudioFormat& format) override {
1874 return true;
1875 }
1876
1877 std::unique_ptr<AudioDecoder> MakeAudioDecoder(
1878 const SdpAudioFormat& format,
1879 absl::optional<AudioCodecPairId> codec_pair_id) override {
1880 auto replacement_file = absl::make_unique<test::ResampleInputAudioFile>(
1881 replacement_file_name_, file_sample_rate_hz_);
1882 replacement_file->set_output_rate_hz(48000);
1883 return absl::make_unique<test::FakeDecodeFromFile>(
1884 std::move(replacement_file), 48000, false);
1885 }
1886
1887 private:
1888 const std::string replacement_file_name_;
1889 const int file_sample_rate_hz_;
1890};
1891
henrik.lundin3c938fc2017-06-14 06:09:58 -07001892// Creates a NetEq test object and all necessary input and output helpers. Runs
1893// the test and returns the NetEqDelayAnalyzer object that was used to
1894// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001895std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001896 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001897 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001898 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001899 const std::string& replacement_file_name,
1900 int file_sample_rate_hz) {
1901 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001902 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001903
1904 constexpr int kReplacementPt = 127;
1905 std::set<uint8_t> cn_types;
1906 std::set<uint8_t> forbidden_types;
1907 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1908 cn_types, forbidden_types));
1909
1910 NetEq::Config config;
1911 config.max_packets_in_buffer = 200;
1912 config.enable_fast_accelerate = true;
1913
1914 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1915
Niels Möller3f651d82018-12-19 15:06:17 +01001916 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001917 new rtc::RefCountedObject<ReplacementAudioDecoderFactory>(
1918 replacement_file_name, file_sample_rate_hz);
Niels Möller3f651d82018-12-19 15:06:17 +01001919
Niels Möller05543682019-01-10 16:55:06 +01001920 test::NetEqTest::DecoderMap codecs = {
1921 {kReplacementPt, SdpAudioFormat("l16", 48000, 1)}};
henrik.lundin3c938fc2017-06-14 06:09:58 -07001922
1923 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1924 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001925 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1926 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001927 test::DefaultNetEqTestErrorCallback error_cb;
1928 test::NetEqTest::Callbacks callbacks;
1929 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001930 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1931 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001932
Niels Möllerbd6dee82019-01-02 09:39:47 +01001933 test::NetEqTest test(config, decoder_factory, codecs, nullptr,
Niels Möller3f651d82018-12-19 15:06:17 +01001934 std::move(input), std::move(output), callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001935 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001936 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001937}
1938} // namespace
1939
Minyue Lic6ff7572018-05-04 09:46:44 +02001940EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001941 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001942 int file_sample_rate_hz) const {
1943 NetEqStatsGetterMap neteq_stats;
1944
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001945 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001946 const uint32_t ssrc = stream.ssrc;
1947 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1948 continue;
1949 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1950 &stream.incoming_packets;
1951 if (audio_packets == nullptr) {
1952 // No incoming audio stream found.
1953 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001954 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001955
Minyue Li27e2b7d2018-05-07 15:20:24 +02001956 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1957
1958 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1959 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1960 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1961 // Could not find output events with SSRC matching the input audio stream.
1962 // Using the first available stream of output events.
1963 output_events_it = parsed_log_.audio_playout_events().cbegin();
1964 }
1965
Danil Chapovalov431abd92018-06-18 12:54:17 +02001966 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001967 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001968 ? absl::nullopt
1969 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001970
1971 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1972 audio_packets, &output_events_it->second, end_time_ms,
1973 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001974 }
1975
Minyue Lic6ff7572018-05-04 09:46:44 +02001976 return neteq_stats;
1977}
1978
Minyue Lic97933f2018-08-10 12:51:15 +02001979// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1980// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001981void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001982 uint32_t ssrc,
1983 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001984 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001985 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1986 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1987 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1988 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1989
Minyue Li01d2a672018-06-21 21:17:19 +02001990 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001991 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1992 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001993
Minyue Lic97933f2018-08-10 12:51:15 +02001994 TimeSeries time_series_packet_arrival("packet arrival delay",
1995 LineStyle::kLine);
1996 TimeSeries time_series_relative_packet_arrival(
1997 "Relative packet arrival delay", LineStyle::kLine);
1998 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
1999 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
2000 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02002001
2002 for (const auto& data : arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002003 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002004 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002005 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002006 }
2007 for (const auto& data : corrected_arrival_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002008 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002009 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002010 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02002011 TimeSeriesPoint(x, y));
2012 }
2013 for (const auto& data : playout_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002014 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002015 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002016 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02002017 }
2018 for (const auto& data : target_delay_ms) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002019 const float x = config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Li45fc6df2018-06-21 11:47:14 +02002020 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02002021 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002022 }
2023
Minyue Lic97933f2018-08-10 12:51:15 +02002024 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
2025 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
2026 plot->AppendTimeSeries(std::move(time_series_play_time));
2027 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07002028
Bjorn Terelius068fc352019-02-13 22:38:25 +01002029 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2030 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002031 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
2032 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002033 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
2034}
2035
Minyue Lic9ac93f2018-06-26 13:01:32 +02002036template <typename NetEqStatsType>
2037void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02002038 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02002039 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
2040 const test::NetEqStatsGetter*)> data_extractor,
2041 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02002042 const std::string& plot_name,
2043 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02002044 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02002045
2046 for (const auto& st : neteq_stats) {
2047 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02002048 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
2049 data_extractor(st.second.get());
2050 for (const auto& data : *data_vector) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002051 const float time =
2052 config_.GetCallTimeSec(data.first * 1000); // ms to us.
Minyue Lic9ac93f2018-06-26 13:01:32 +02002053 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002054 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02002055 }
2056 }
2057
2058 for (auto& series : time_series) {
2059 series.second.label = GetStreamName(kIncomingPacket, series.first);
2060 series.second.line_style = LineStyle::kLine;
2061 plot->AppendTimeSeries(std::move(series.second));
2062 }
2063
Bjorn Terelius068fc352019-02-13 22:38:25 +01002064 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2065 "Time (s)", kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02002066 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02002067 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07002068}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002069
Minyue Lic9ac93f2018-06-26 13:01:32 +02002070void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
2071 const NetEqStatsGetterMap& neteq_stats,
2072 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
2073 const std::string& plot_name,
2074 Plot* plot) const {
2075 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
2076 neteq_stats,
2077 [](const test::NetEqStatsGetter* stats_getter) {
2078 return stats_getter->stats();
2079 },
2080 stats_extractor, plot_name, plot);
2081}
2082
2083void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
2084 const NetEqStatsGetterMap& neteq_stats,
2085 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
2086 const std::string& plot_name,
2087 Plot* plot) const {
2088 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
2089 neteq_stats,
2090 [](const test::NetEqStatsGetter* stats_getter) {
2091 return stats_getter->lifetime_stats();
2092 },
2093 stats_extractor, plot_name, plot);
2094}
2095
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002096void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
2097 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002098 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002099 if (configs_by_cp_id.find(config.candidate_pair_id) ==
2100 configs_by_cp_id.end()) {
2101 const std::string candidate_pair_desc =
2102 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08002103 configs_by_cp_id[config.candidate_pair_id] =
2104 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
2105 candidate_pair_desc,
2106 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002107 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2108 candidate_pair_desc;
2109 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002110 float x = config_.GetCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002111 float y = static_cast<float>(config.type);
2112 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
2113 }
2114
2115 // TODO(qingsi): There can be a large number of candidate pairs generated by
2116 // certain calls and the frontend cannot render the chart in this case due to
2117 // the failure of generating a palette with the same number of colors.
2118 for (auto& kv : configs_by_cp_id) {
2119 plot->AppendTimeSeries(std::move(kv.second));
2120 }
2121
Bjorn Terelius068fc352019-02-13 22:38:25 +01002122 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2123 "Time (s)", kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002124 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
2125 kTopMargin);
2126 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
2127}
2128
2129std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
2130 uint32_t candidate_pair_id) {
2131 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
2132 candidate_pair_desc_by_id_.end()) {
2133 return candidate_pair_desc_by_id_[candidate_pair_id];
2134 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002135 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002136 // TODO(qingsi): Add the handling of the "Updated" config event after the
2137 // visualization of property change for candidate pairs is introduced.
2138 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
2139 candidate_pair_desc_by_id_.end()) {
2140 const std::string candidate_pair_desc =
2141 GetCandidatePairLogDescriptionAsString(config);
2142 candidate_pair_desc_by_id_[config.candidate_pair_id] =
2143 candidate_pair_desc;
2144 }
2145 }
2146 return candidate_pair_desc_by_id_[candidate_pair_id];
2147}
2148
2149void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
2150 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002151 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002152 if (checks_by_cp_id.find(event.candidate_pair_id) ==
2153 checks_by_cp_id.end()) {
2154 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08002155 "[" + std::to_string(event.candidate_pair_id) + "]" +
2156 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002157 LineStyle::kNone, PointStyle::kHighlight);
2158 }
Bjorn Terelius068fc352019-02-13 22:38:25 +01002159 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein6353fbc2018-12-03 14:35:59 -08002160 constexpr int kIceCandidatePairEventTypeOffset =
2161 static_cast<int>(IceCandidatePairConfigType::kNumValues);
2162 float y = static_cast<float>(event.type) + kIceCandidatePairEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002163 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2164 }
2165
2166 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2167 for (auto& kv : checks_by_cp_id) {
2168 plot->AppendTimeSeries(std::move(kv.second));
2169 }
2170
Bjorn Terelius068fc352019-02-13 22:38:25 +01002171 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2172 "Time (s)", kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002173 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
2174 kTopMargin);
2175 plot->SetTitle("[IceEventLog] ICE connectivity checks");
2176}
2177
Zach Stein10a58012018-12-07 12:26:28 -08002178void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
2179 TimeSeries states("DTLS Transport State", LineStyle::kNone,
2180 PointStyle::kHighlight);
2181 for (const auto& event : parsed_log_.dtls_transport_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002182 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002183 float y = static_cast<float>(event.dtls_transport_state);
2184 states.points.emplace_back(x, y);
2185 }
2186 plot->AppendTimeSeries(std::move(states));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002187 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2188 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002189 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
2190 "Numeric Transport State", kBottomMargin, kTopMargin);
2191 plot->SetTitle("DTLS Transport State");
2192}
2193
2194void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2195 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2196 PointStyle::kHighlight);
2197 for (const auto& event : parsed_log_.dtls_writable_states()) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002198 float x = config_.GetCallTimeSec(event.log_time_us());
Zach Stein10a58012018-12-07 12:26:28 -08002199 float y = static_cast<float>(event.writable);
2200 writable.points.emplace_back(x, y);
2201 }
2202 plot->AppendTimeSeries(std::move(writable));
Bjorn Terelius068fc352019-02-13 22:38:25 +01002203 plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
2204 "Time (s)", kLeftMargin, kRightMargin);
Zach Stein10a58012018-12-07 12:26:28 -08002205 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2206 plot->SetTitle("DTLS Writable State");
2207}
2208
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002209void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002210 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002211 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2212 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2213 }
2214 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2215 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2216 }
2217 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2218 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2219 }
2220 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2221 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2222 }
2223 for (const auto& alert : incoming_seq_num_jumps_) {
2224 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2225 }
2226 for (const auto& alert : incoming_capture_time_jumps_) {
2227 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2228 }
2229 for (const auto& alert : outgoing_seq_num_jumps_) {
2230 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2231 }
2232 for (const auto& alert : outgoing_capture_time_jumps_) {
2233 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2234 }
2235 for (const auto& alert : outgoing_high_loss_alerts_) {
2236 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002237 }
2238 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2239}
2240
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002241void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2242 // With 100 packets/s (~800kbps), false positives would require 10 s without
2243 // data.
2244 constexpr int64_t kMaxSeqNumJump = 1000;
2245 // With a 90 kHz clock, false positives would require 10 s without data.
2246 constexpr int64_t kMaxCaptureTimeJump = 900000;
2247
2248 int64_t end_time_us = log_segments_.empty()
2249 ? std::numeric_limits<int64_t>::max()
2250 : log_segments_.front().second;
2251
2252 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002253 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002254 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002255 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002256 // Check for gaps in sequence numbers and capture timestamps.
2257 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2258 for (const auto& packet : stream.packet_view) {
2259 if (packet.log_time_us() > end_time_us) {
2260 // Only process the first (LOG_START, LOG_END) segment.
2261 break;
2262 }
2263
2264 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2265 if (last_seq_num.has_value() &&
2266 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002267 Alert_SeqNumJump(direction,
2268 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002269 packet.header.ssrc);
2270 }
2271 last_seq_num.emplace(seq_num);
2272
2273 int64_t capture_time =
2274 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2275 if (last_capture_time.has_value() &&
2276 std::abs(capture_time - last_capture_time.value()) >
2277 kMaxCaptureTimeJump) {
Bjorn Terelius068fc352019-02-13 22:38:25 +01002278 Alert_CaptureTimeJump(direction,
2279 config_.GetCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002280 packet.header.ssrc);
2281 }
2282 last_capture_time.emplace(capture_time);
2283 }
2284 }
2285}
2286
2287void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2288 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2289 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2290 int64_t end_time_us = log_segments_.empty()
2291 ? std::numeric_limits<int64_t>::max()
2292 : log_segments_.front().second;
2293
2294 // TODO(terelius): The parser could provide a list of all packets, ordered
2295 // by time, for each direction.
2296 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2297 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2298 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2299 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2300 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002301 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002302 for (const auto& kv : rtp_in_direction) {
2303 int64_t timestamp = kv.first;
2304 if (timestamp > end_time_us) {
2305 // Only process the first (LOG_START, LOG_END) segment.
2306 break;
2307 }
2308 int64_t duration = timestamp - last_rtp_time.value_or(0);
2309 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2310 // No packet sent/received for more than 500 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002311 Alert_RtpLogTimeGap(direction, config_.GetCallTimeSec(timestamp),
2312 duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002313 }
2314 last_rtp_time.emplace(timestamp);
2315 }
2316
Danil Chapovalov431abd92018-06-18 12:54:17 +02002317 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002318 if (direction == kIncomingPacket) {
2319 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2320 if (rtcp.log_time_us() > end_time_us) {
2321 // Only process the first (LOG_START, LOG_END) segment.
2322 break;
2323 }
2324 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2325 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2326 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002327 Alert_RtcpLogTimeGap(direction,
2328 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002329 duration / 1000);
2330 }
2331 last_rtcp_time.emplace(rtcp.log_time_us());
2332 }
2333 } else {
2334 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2335 if (rtcp.log_time_us() > end_time_us) {
2336 // Only process the first (LOG_START, LOG_END) segment.
2337 break;
2338 }
2339 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2340 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2341 // No feedback sent/received for more than 2000 ms.
Bjorn Terelius068fc352019-02-13 22:38:25 +01002342 Alert_RtcpLogTimeGap(direction,
2343 config_.GetCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002344 duration / 1000);
2345 }
2346 last_rtcp_time.emplace(rtcp.log_time_us());
2347 }
2348 }
2349}
2350
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002351// TODO(terelius): Notifications could possibly be generated by the same code
2352// that produces the graphs. There is some code duplication that could be
2353// avoided, but that might be solved anyway when we move functionality from the
2354// analyzer to the parser.
2355void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002356 CreateStreamGapAlerts(kIncomingPacket);
2357 CreateStreamGapAlerts(kOutgoingPacket);
2358 CreateTransmissionGapAlerts(kIncomingPacket);
2359 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002360
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002361 int64_t end_time_us = log_segments_.empty()
2362 ? std::numeric_limits<int64_t>::max()
2363 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002364
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002365 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002366 // Loss feedback
2367 int64_t total_lost_packets = 0;
2368 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002369 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2370 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002371 // Only process the first (LOG_START, LOG_END) segment.
2372 break;
2373 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002374 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002375 bwe_update.expected_packets;
2376 total_lost_packets += lost_packets;
2377 total_expected_packets += bwe_update.expected_packets;
2378 }
2379 double avg_outgoing_loss =
2380 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002381 if (avg_outgoing_loss > kMaxLossFraction) {
2382 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002383 }
2384}
2385
terelius54ce6802016-07-13 06:44:41 -07002386} // namespace webrtc