blob: f603784e03cd8052c9616597dbbb78751c9091d5 [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"
Sebastian Jansson95edb032019-01-17 16:24:12 +010022#include "api/transport/field_trial_based_config.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020023#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020024#include "call/audio_receive_stream.h"
25#include "call/audio_send_stream.h"
26#include "call/call.h"
27#include "call/video_receive_stream.h"
28#include "call/video_send_stream.h"
Mirko Bonadei71207422017-09-15 13:58:09 +020029#include "common_types.h" // NOLINT(build/include)
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"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020057#include "rtc_base/function_view.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020058#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020059#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020060#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020061#include "rtc_base/strings/string_builder.h"
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;
142 uint64_t first_rtp_timestamp =
143 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
144 int64_t first_log_timestamp = packets[0].log_time_us();
145 uint64_t last_rtp_timestamp = first_rtp_timestamp;
146 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(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200291 rtc::FunctionView<float(int64_t)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200292 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200293 const IterableType& data_view,
294 int64_t begin_time,
295 int64_t end_time,
296 int64_t window_duration_us,
297 int64_t step,
298 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700299 size_t window_index_begin = 0;
300 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700301 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700302
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200303 for (int64_t t = begin_time; t < end_time + step; t += step) {
304 while (window_index_end < data_view.size() &&
305 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200306 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700307 if (value)
308 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700309 ++window_index_end;
310 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200311 while (window_index_begin < data_view.size() &&
312 data_view[window_index_begin].log_time_us() <
313 t - window_duration_us) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200314 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700315 if (value)
316 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700317 ++window_index_begin;
318 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800319 float window_duration_s =
320 static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200321 float x = fx(t);
terelius53dc23c2017-03-13 05:24:05 -0700322 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700323 result->points.emplace_back(x, y);
324 }
325}
326
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800327const char kUnknownEnumValue[] = "unknown";
328
329const char kIceCandidateTypeLocal[] = "local";
330const char kIceCandidateTypeStun[] = "stun";
331const char kIceCandidateTypePrflx[] = "prflx";
332const char kIceCandidateTypeRelay[] = "relay";
333
334const char kProtocolUdp[] = "udp";
335const char kProtocolTcp[] = "tcp";
336const char kProtocolSsltcp[] = "ssltcp";
337const char kProtocolTls[] = "tls";
338
339const char kAddressFamilyIpv4[] = "ipv4";
340const char kAddressFamilyIpv6[] = "ipv6";
341
342const char kNetworkTypeEthernet[] = "ethernet";
343const char kNetworkTypeLoopback[] = "loopback";
344const char kNetworkTypeWifi[] = "wifi";
345const char kNetworkTypeVpn[] = "vpn";
346const char kNetworkTypeCellular[] = "cellular";
347
348std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
349 switch (type) {
350 case webrtc::IceCandidateType::kLocal:
351 return kIceCandidateTypeLocal;
352 case webrtc::IceCandidateType::kStun:
353 return kIceCandidateTypeStun;
354 case webrtc::IceCandidateType::kPrflx:
355 return kIceCandidateTypePrflx;
356 case webrtc::IceCandidateType::kRelay:
357 return kIceCandidateTypeRelay;
358 default:
359 return kUnknownEnumValue;
360 }
361}
362
363std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
364 switch (protocol) {
365 case webrtc::IceCandidatePairProtocol::kUdp:
366 return kProtocolUdp;
367 case webrtc::IceCandidatePairProtocol::kTcp:
368 return kProtocolTcp;
369 case webrtc::IceCandidatePairProtocol::kSsltcp:
370 return kProtocolSsltcp;
371 case webrtc::IceCandidatePairProtocol::kTls:
372 return kProtocolTls;
373 default:
374 return kUnknownEnumValue;
375 }
376}
377
378std::string GetAddressFamilyAsString(
379 webrtc::IceCandidatePairAddressFamily family) {
380 switch (family) {
381 case webrtc::IceCandidatePairAddressFamily::kIpv4:
382 return kAddressFamilyIpv4;
383 case webrtc::IceCandidatePairAddressFamily::kIpv6:
384 return kAddressFamilyIpv6;
385 default:
386 return kUnknownEnumValue;
387 }
388}
389
390std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
391 switch (type) {
392 case webrtc::IceCandidateNetworkType::kEthernet:
393 return kNetworkTypeEthernet;
394 case webrtc::IceCandidateNetworkType::kLoopback:
395 return kNetworkTypeLoopback;
396 case webrtc::IceCandidateNetworkType::kWifi:
397 return kNetworkTypeWifi;
398 case webrtc::IceCandidateNetworkType::kVpn:
399 return kNetworkTypeVpn;
400 case webrtc::IceCandidateNetworkType::kCellular:
401 return kNetworkTypeCellular;
402 default:
403 return kUnknownEnumValue;
404 }
405}
406
407std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200408 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800409 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
410 // represents a pair of a local server-reflexive candidate on a WiFi network
411 // and a remote relay candidate using TCP as the relay protocol on a cell
412 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200413 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800414 std::string local_candidate_type =
415 GetIceCandidateTypeAsString(config.local_candidate_type);
416 std::string remote_candidate_type =
417 GetIceCandidateTypeAsString(config.remote_candidate_type);
418 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
419 local_candidate_type +=
420 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
421 }
422 ss << local_candidate_type << ":"
423 << GetNetworkTypeAsString(config.local_network_type) << ":"
424 << GetAddressFamilyAsString(config.local_address_family) << "->"
425 << remote_candidate_type << ":"
426 << GetAddressFamilyAsString(config.remote_address_family) << "@"
427 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200428 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800429}
430
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200431std::string GetDirectionAsString(PacketDirection direction) {
432 if (direction == kIncomingPacket) {
433 return "Incoming";
434 } else {
435 return "Outgoing";
436 }
437}
438
439std::string GetDirectionAsShortString(PacketDirection direction) {
440 if (direction == kIncomingPacket) {
441 return "In";
442 } else {
443 return "Out";
444 }
445}
446
terelius54ce6802016-07-13 06:44:41 -0700447} // namespace
448
Sebastian Janssonb290a6d2019-01-03 14:46:23 +0100449EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200450 bool normalize_time)
451 : parsed_log_(log),
452 window_duration_(250000),
453 step_(10000),
454 normalize_time_(normalize_time) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200455 begin_time_ = parsed_log_.first_timestamp();
456 end_time_ = parsed_log_.last_timestamp();
457 if (end_time_ < begin_time_) {
458 RTC_LOG(LS_WARNING) << "No useful events in the log.";
459 begin_time_ = end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000460 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200461 call_duration_s_ = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200462
463 const auto& log_start_events = parsed_log_.start_log_events();
464 const auto& log_end_events = parsed_log_.stop_log_events();
465 auto start_iter = log_start_events.begin();
466 auto end_iter = log_end_events.begin();
467 while (start_iter != log_start_events.end()) {
468 int64_t start = start_iter->log_time_us();
469 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200470 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200471 if (start_iter != log_start_events.end())
472 next_start.emplace(start_iter->log_time_us());
473 if (end_iter != log_end_events.end() &&
474 end_iter->log_time_us() <=
475 next_start.value_or(std::numeric_limits<int64_t>::max())) {
476 int64_t end = end_iter->log_time_us();
477 RTC_DCHECK_LE(start, end);
478 log_segments_.push_back(std::make_pair(start, end));
479 ++end_iter;
480 } else {
481 // we're missing an end event. Assume that it occurred just before the
482 // next start.
483 log_segments_.push_back(
484 std::make_pair(start, next_start.value_or(end_time_)));
485 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700486 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100487 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200488 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700489}
490
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200491class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200492 public:
493 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
494
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200495 void Update(NetworkControlUpdate update) {
496 if (update.target_rate) {
497 last_bitrate_bps_ = update.target_rate->target_rate.bps();
498 bitrate_updated_ = true;
499 }
Stefan Holmer13181032016-07-29 14:48:54 +0200500 }
501
502 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
503 uint32_t bitrate) override {}
504
505 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
506 bool GetAndResetBitrateUpdated() {
507 bool bitrate_updated = bitrate_updated_;
508 bitrate_updated_ = false;
509 return bitrate_updated;
510 }
511
512 private:
513 uint32_t last_bitrate_bps_;
514 bool bitrate_updated_;
515};
516
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200517int64_t EventLogAnalyzer::ToCallTimeUs(int64_t timestamp) const {
518 int64_t begin_time = 0;
519 if (normalize_time_) {
520 begin_time = begin_time_;
521 }
522 return timestamp - begin_time;
523}
524
525float EventLogAnalyzer::ToCallTimeSec(int64_t timestamp) const {
526 return static_cast<float>(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100527}
528
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200529void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700530 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200531 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
532 // Filter on SSRC.
533 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700534 continue;
terelius54ce6802016-07-13 06:44:41 -0700535 }
terelius54ce6802016-07-13 06:44:41 -0700536
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200537 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
538 LineStyle::kBar);
539 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200540 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200541 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200542 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
543 return this->ToCallTimeSec(packet.log_time_us());
544 };
545 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
546 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700547 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700548 }
549
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200550 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
551 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700552 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
553 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200554 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700555}
556
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200557template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700558void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700559 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200560 const IterableType& packets,
561 const std::string& label) {
562 TimeSeries time_series(label, LineStyle::kStep);
563 for (size_t i = 0; i < packets.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200564 float x = ToCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200565 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700566 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200567 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700568}
569
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200570void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
571 Plot* plot) {
572 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
573 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
574 continue;
575 std::string label =
576 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
577 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
578 }
579 std::string label =
580 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
581 if (direction == kIncomingPacket) {
582 CreateAccumulatedPacketsTimeSeries(
583 plot, parsed_log_.incoming_rtcp_packets(), label);
584 } else {
585 CreateAccumulatedPacketsTimeSeries(
586 plot, parsed_log_.outgoing_rtcp_packets(), label);
587 }
philipelccd74892016-09-05 02:46:25 -0700588
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200589 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
590 kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700591 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200592 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
593 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700594}
595
terelius54ce6802016-07-13 06:44:41 -0700596// For each SSRC, plot the time between the consecutive playouts.
597void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200598 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
599 uint32_t ssrc = playout_stream.first;
600 if (!MatchingSsrc(ssrc, desired_ssrc_))
601 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200602 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200603 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200604 for (const auto& playout_event : playout_stream.second) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200605 float x = ToCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200606 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200607 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200608 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200609 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200610 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700611 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200612 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700613 }
614
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200615 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
616 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700617 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
618 kTopMargin);
619 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700620}
621
ivocaac9d6f2016-09-22 07:01:47 -0700622// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200623void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
624 Plot* plot) {
625 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
626 if (!IsAudioSsrc(direction, stream.ssrc))
627 continue;
628 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
629 LineStyle::kLine);
630 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700631 if (packet.header.extension.hasAudioLevel) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200632 float x = ToCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700633 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
634 // Here we convert it to dBov.
635 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200636 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700637 }
638 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200639 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700640 }
641
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200642 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
643 kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200644 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200645 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700646}
647
terelius54ce6802016-07-13 06:44:41 -0700648// For each SSRC, plot the time between the consecutive playouts.
649void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200650 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
651 // Filter on SSRC.
652 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700653 continue;
terelius54ce6802016-07-13 06:44:41 -0700654 }
terelius54ce6802016-07-13 06:44:41 -0700655
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200656 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
657 LineStyle::kBar);
658 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
659 const LoggedRtpPacketIncoming& new_packet) {
660 int64_t diff =
661 WrappingDifference(new_packet.rtp.header.sequenceNumber,
662 old_packet.rtp.header.sequenceNumber, 1ul << 16);
663 return diff;
664 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200665 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
666 return this->ToCallTimeSec(packet.log_time_us());
667 };
668 ProcessPairs<LoggedRtpPacketIncoming, float>(
669 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
670 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700671 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700672 }
673
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200674 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
675 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700676 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
677 kTopMargin);
678 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700679}
680
Stefan Holmer99f8e082016-09-09 13:37:50 +0200681void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200682 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
683 const std::vector<LoggedRtpPacketIncoming>& packets =
684 stream.incoming_packets;
685 // Filter on SSRC.
686 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200687 continue;
688 }
689
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200690 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
691 LineStyle::kLine, PointStyle::kHighlight);
692 // TODO(terelius): Should the window and step size be read from the class
693 // instead?
694 const int64_t kWindowUs = 1000000;
695 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100696 SeqNumUnwrapper<uint16_t> unwrapper_;
697 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800698 size_t window_index_begin = 0;
699 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200700 uint64_t highest_seq_number =
701 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
702 uint64_t highest_prior_seq_number =
703 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800704
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200705 for (int64_t t = begin_time_; t < end_time_ + kStep; t += kStep) {
706 while (window_index_end < packets.size() &&
707 packets[window_index_end].rtp.log_time_us() < t) {
708 uint64_t sequence_number = unwrapper_.Unwrap(
709 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800710 highest_seq_number = std::max(highest_seq_number, sequence_number);
711 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200712 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200713 while (window_index_begin < packets.size() &&
714 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
715 uint64_t sequence_number = prior_unwrapper_.Unwrap(
716 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800717 highest_prior_seq_number =
718 std::max(highest_prior_seq_number, sequence_number);
719 ++window_index_begin;
720 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200721 float x = ToCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200722 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800723 if (expected_packets > 0) {
724 int64_t received_packets = window_index_end - window_index_begin;
725 int64_t lost_packets = expected_packets - received_packets;
726 float y = static_cast<float>(lost_packets) / expected_packets * 100;
727 time_series.points.emplace_back(x, y);
728 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200729 }
philipel35ba9bd2017-04-19 05:58:51 -0700730 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200731 }
732
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200733 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
734 kLeftMargin, kRightMargin);
Stefan Holmer99f8e082016-09-09 13:37:50 +0200735 plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
736 kTopMargin);
737 plot->SetTitle("Estimated incoming loss rate");
738}
739
terelius2ee076d2017-08-15 02:04:02 -0700740void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100741 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200742 // Filter on SSRC.
743 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200744 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700745 continue;
746 }
terelius54ce6802016-07-13 06:44:41 -0700747
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100748 const std::vector<LoggedRtpPacketIncoming>& packets =
749 stream.incoming_packets;
750 if (packets.size() < 100) {
751 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
752 << packets.size() << " packets in the stream.";
753 continue;
754 }
755 int64_t end_time_us = log_segments_.empty()
756 ? std::numeric_limits<int64_t>::max()
757 : log_segments_.front().second;
758 absl::optional<uint32_t> estimated_frequency =
759 EstimateRtpClockFrequency(packets, end_time_us);
760 if (!estimated_frequency)
761 continue;
762 const double frequency_hz = *estimated_frequency;
763 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
764 RTC_LOG(LS_WARNING)
765 << "Video stream should use a 90 kHz clock but appears to use "
766 << frequency_hz / 1000 << ". Discarding.";
767 continue;
768 }
769
770 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
771 return this->ToCallTimeSec(packet.log_time_us());
772 };
773 auto ToNetworkDelay = [frequency_hz](
774 const LoggedRtpPacketIncoming& old_packet,
775 const LoggedRtpPacketIncoming& new_packet) {
776 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
777 };
778
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200779 TimeSeries capture_time_data(
780 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
781 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100782 AccumulatePairs<LoggedRtpPacketIncoming, double>(
783 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700784 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700785
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200786 TimeSeries send_time_data(
787 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
788 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100789 AccumulatePairs<LoggedRtpPacketIncoming, double>(
790 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
791 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700792 }
793
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200794 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
795 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700796 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
797 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700798 plot->SetTitle("Network latency (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700799}
800
tereliusf736d232016-08-04 10:00:11 -0700801// Plot the fraction of packets lost (as perceived by the loss-based BWE).
802void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100803 TimeSeries time_series("Fraction lost", LineStyle::kLine,
804 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200805 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200806 float x = ToCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200807 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700808 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700809 }
tereliusf736d232016-08-04 10:00:11 -0700810
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200811 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200812 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
813 kLeftMargin, kRightMargin);
tereliusf736d232016-08-04 10:00:11 -0700814 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
815 kTopMargin);
816 plot->SetTitle("Reported packet loss");
817}
818
terelius54ce6802016-07-13 06:44:41 -0700819// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200820void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
821 // TODO(terelius): This could be provided by the parser.
822 std::multimap<int64_t, size_t> packets_in_order;
823 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
824 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
825 packets_in_order.insert(
826 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700827 }
828
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200829 auto window_begin = packets_in_order.begin();
830 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700831 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700832
833 // Calculate a moving average of the bitrate and store in a TimeSeries.
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100834 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200835 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
836 while (window_end != packets_in_order.end() && window_end->first < time) {
837 bytes_in_window += window_end->second;
838 ++window_end;
terelius54ce6802016-07-13 06:44:41 -0700839 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200840 while (window_begin != packets_in_order.end() &&
841 window_begin->first < time - window_duration_) {
842 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
843 bytes_in_window -= window_begin->second;
844 ++window_begin;
845 }
846 float window_duration_in_seconds =
847 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200848 float x = ToCallTimeSec(time);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200849 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
850 bitrate_series.points.emplace_back(x, y);
851 }
852 plot->AppendTimeSeries(std::move(bitrate_series));
853
854 // Overlay the outgoing REMB over incoming bitrate.
855 TimeSeries remb_series("Remb", LineStyle::kStep);
856 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200857 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200858 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
859 remb_series.points.emplace_back(x, y);
860 }
861 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
862
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200863 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
864 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200865 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
866 plot->SetTitle("Incoming RTP bitrate");
867}
868
869// Plot the total bandwidth used by all RTP streams.
870void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
871 bool show_detector_state,
872 bool show_alr_state) {
873 // TODO(terelius): This could be provided by the parser.
874 std::multimap<int64_t, size_t> packets_in_order;
875 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
876 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
877 packets_in_order.insert(
878 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
879 }
880
881 auto window_begin = packets_in_order.begin();
882 auto window_end = packets_in_order.begin();
883 size_t bytes_in_window = 0;
884
885 // Calculate a moving average of the bitrate and store in a TimeSeries.
886 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
887 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
888 while (window_end != packets_in_order.end() && window_end->first < time) {
889 bytes_in_window += window_end->second;
890 ++window_end;
891 }
892 while (window_begin != packets_in_order.end() &&
893 window_begin->first < time - window_duration_) {
894 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
895 bytes_in_window -= window_begin->second;
896 ++window_begin;
terelius54ce6802016-07-13 06:44:41 -0700897 }
898 float window_duration_in_seconds =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800899 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200900 float x = ToCallTimeSec(time);
terelius54ce6802016-07-13 06:44:41 -0700901 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
philipel35ba9bd2017-04-19 05:58:51 -0700902 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700903 }
philipel35ba9bd2017-04-19 05:58:51 -0700904 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700905
terelius8058e582016-07-25 01:32:41 -0700906 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200907 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
908 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200909 float x = ToCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200910 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
911 loss_series.points.emplace_back(x, y);
912 }
philipel10fc0e62017-04-11 01:50:23 -0700913
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200914 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
915 IntervalSeries overusing_series("Overusing", "#ff8e82",
916 IntervalSeries::kHorizontal);
917 IntervalSeries underusing_series("Underusing", "#5092fc",
918 IntervalSeries::kHorizontal);
919 IntervalSeries normal_series("Normal", "#c4ffc4",
920 IntervalSeries::kHorizontal);
921 IntervalSeries* last_series = &normal_series;
922 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700923
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200924 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700925
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200926 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200927 float x = ToCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200928 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700929
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200930 if (last_detector_state != delay_update.detector_state) {
931 last_series->intervals.emplace_back(last_detector_switch, x);
932 last_detector_state = delay_update.detector_state;
933 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700934
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200935 switch (delay_update.detector_state) {
936 case BandwidthUsage::kBwNormal:
937 last_series = &normal_series;
938 break;
939 case BandwidthUsage::kBwUnderusing:
940 last_series = &underusing_series;
941 break;
942 case BandwidthUsage::kBwOverusing:
943 last_series = &overusing_series;
944 break;
945 case BandwidthUsage::kLast:
946 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200947 }
948 }
philipel23c7f252017-07-14 06:30:03 -0700949
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200950 delay_series.points.emplace_back(x, y);
951 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200952
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200953 RTC_CHECK(last_series);
954 last_series->intervals.emplace_back(last_detector_switch, end_time_);
955
956 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
957 PointStyle::kHighlight);
958 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200959 float x = ToCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200960 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
961 created_series.points.emplace_back(x, y);
962 }
963
964 TimeSeries result_series("Probing results.", LineStyle::kNone,
965 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200966 for (auto& result : parsed_log_.bwe_probe_success_events()) {
967 float x = ToCallTimeSec(result.log_time_us());
968 float y = static_cast<float>(result.bitrate_bps) / 1000;
969 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200970 }
971
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -0800972 TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
973 PointStyle::kHighlight);
974 for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
975 float x = ToCallTimeSec(failure.log_time_us());
976 probe_failures_series.points.emplace_back(x, 0);
977 }
978
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200979 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
980 bool previously_in_alr = false;
981 int64_t alr_start = 0;
982 for (auto& alr : parsed_log_.alr_state_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200983 float y = ToCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200984 if (!previously_in_alr && alr.in_alr) {
985 alr_start = alr.log_time_us();
986 previously_in_alr = true;
987 } else if (previously_in_alr && !alr.in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200988 float x = ToCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100989 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200990 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +0000991 }
Björn Tereliusff612732018-04-25 14:23:01 +0000992 }
993
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200994 if (previously_in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200995 float x = ToCallTimeSec(alr_start);
996 float y = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200997 alr_state.intervals.emplace_back(x, y);
998 }
999
1000 if (show_detector_state) {
1001 plot->AppendIntervalSeries(std::move(overusing_series));
1002 plot->AppendIntervalSeries(std::move(underusing_series));
1003 plot->AppendIntervalSeries(std::move(normal_series));
1004 }
1005
1006 if (show_alr_state) {
1007 plot->AppendIntervalSeries(std::move(alr_state));
1008 }
1009 plot->AppendTimeSeries(std::move(loss_series));
Piotr (Peter) Slatalaf996c842019-01-04 06:54:22 -08001010 plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001011 plot->AppendTimeSeries(std::move(delay_series));
1012 plot->AppendTimeSeries(std::move(created_series));
1013 plot->AppendTimeSeries(std::move(result_series));
1014
1015 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001016 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001017 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001018 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001019 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001020 remb_series.points.emplace_back(x, y);
1021 }
1022 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1023
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001024 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1025 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001026 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001027 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001028}
1029
1030// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001031void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1032 Plot* plot) {
1033 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1034 // Filter on SSRC.
1035 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001036 continue;
terelius54ce6802016-07-13 06:44:41 -07001037 }
1038
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001039 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1040 LineStyle::kLine);
1041 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1042 return packet.total_length * 8.0 / 1000.0;
1043 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001044 auto ToCallTime = [this](int64_t time) {
1045 return this->ToCallTimeSec(time);
1046 };
terelius53dc23c2017-03-13 05:24:05 -07001047 MovingAverage<LoggedRtpPacket, double>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001048 ToCallTime, GetPacketSizeKilobits, stream.packet_view, begin_time_,
1049 end_time_, window_duration_, step_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001050 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001051 }
1052
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001053 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1054 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001055 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001056 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001057}
1058
Bjorn Terelius28db2662017-10-04 14:22:43 +02001059void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001060 using RtpPacketType = LoggedRtpPacketOutgoing;
1061 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001062
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001063 // TODO(terelius): This could be provided by the parser.
1064 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1065 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1066 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1067 outgoing_rtp.insert(
1068 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001069 }
1070
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001071 const std::vector<TransportFeedbackType>& incoming_rtcp =
1072 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001073
1074 SimulatedClock clock(0);
1075 BitrateObserver observer;
1076 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001077 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001078 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Janssona39a0072018-10-15 20:59:07 +02001079 TransportFeedbackAdapter transport_feedback(&clock);
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001080 auto factory = GoogCcNetworkControllerFactory(&null_event_log);
1081 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001082 // TODO(holmer): Log the call config and use that here instead.
1083 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001084 NetworkControllerConfig cc_config;
Sebastian Jansson78416b62018-10-18 13:08:17 +02001085 cc_config.constraints.at_time = Timestamp::us(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001086 cc_config.constraints.starting_rate = DataRate::bps(kDefaultStartBitrateBps);
1087 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001088
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001089 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1090 PointStyle::kHighlight);
1091 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1092 PointStyle::kHighlight);
1093 TimeSeries acked_estimate_time_series(
1094 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001095
1096 auto rtp_iterator = outgoing_rtp.begin();
1097 auto rtcp_iterator = incoming_rtcp.begin();
1098
1099 auto NextRtpTime = [&]() {
1100 if (rtp_iterator != outgoing_rtp.end())
1101 return static_cast<int64_t>(rtp_iterator->first);
1102 return std::numeric_limits<int64_t>::max();
1103 };
1104
1105 auto NextRtcpTime = [&]() {
1106 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001107 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001108 return std::numeric_limits<int64_t>::max();
1109 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001110 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001111
1112 auto NextProcessTime = [&]() {
1113 if (rtcp_iterator != incoming_rtcp.end() ||
1114 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001115 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001116 }
1117 return std::numeric_limits<int64_t>::max();
1118 };
1119
Stefan Holmer492ee282016-10-27 17:19:20 +02001120 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001121#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson95edb032019-01-17 16:24:12 +01001122 FieldTrialBasedConfig field_trial_config_;
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001123 // The event_log_visualizer should normally not be compiled with
1124 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1125 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1126 // and piping the output to plot_dynamics.py can be used as a hack to get the
1127 // internal state of various BWE components. In this case, it is important
1128 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1129 // SendSideCongestionController since that would lead to duplicate outputs.
1130 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Sebastian Jansson95edb032019-01-17 16:24:12 +01001131 &field_trial_config_,
1132 absl::make_unique<BitrateEstimator>(&field_trial_config_));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001133#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001134 int64_t time_us =
1135 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001136 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001137 while (time_us != std::numeric_limits<int64_t>::max()) {
1138 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001139 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1140 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1141 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1142 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1143 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
1144 transport_feedback.AddPacket(
1145 rtp_packet.rtp.header.ssrc,
1146 rtp_packet.rtp.header.extension.transportSequenceNumber,
1147 rtp_packet.rtp.total_length, PacedPacketInfo());
1148 rtc::SentPacket sent_packet(
1149 rtp_packet.rtp.header.extension.transportSequenceNumber,
1150 rtp_packet.rtp.log_time_us() / 1000);
1151 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1152 if (sent_msg)
1153 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1154 }
1155 ++rtp_iterator;
1156 }
Stefan Holmer13181032016-07-29 14:48:54 +02001157 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001158 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001159
1160 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
1161 rtcp_iterator->transport_feedback);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001162 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001163 if (feedback_msg) {
1164 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
1165 std::vector<PacketFeedback> feedback =
1166 transport_feedback.GetTransportFeedbackVector();
1167 SortPacketFeedbackVector(&feedback);
1168 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001169#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001170 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001171#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001172 for (const PacketFeedback& packet : feedback)
1173 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1174 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
1175 }
Stefan Holmer13181032016-07-29 14:48:54 +02001176 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001177
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001178 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001179 float y = bitrate_bps.value_or(0) / 1000;
1180 acked_time_series.points.emplace_back(x, y);
1181#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1182 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1183 acked_estimate_time_series.points.emplace_back(x, y);
1184#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001185 ++rtcp_iterator;
1186 }
stefanc3de0332016-08-02 07:22:17 -07001187 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1188 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001189 ProcessInterval msg;
1190 msg.at_time = Timestamp::us(clock.TimeInMicroseconds());
1191 observer.Update(goog_cc->OnProcessInterval(msg));
1192 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001193 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001194 if (observer.GetAndResetBitrateUpdated() ||
1195 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001196 uint32_t y = observer.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001197 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001198 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001199 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001200 }
1201 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1202 }
1203 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001204 plot->AppendTimeSeries(std::move(time_series));
1205 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001206 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001207
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001208 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1209 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001210 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001211 plot->SetTitle("Simulated send-side BWE behavior");
1212}
1213
1214void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001215 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001216 class RembInterceptingPacketRouter : public PacketRouter {
1217 public:
1218 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1219 uint32_t bitrate_bps) override {
1220 last_bitrate_bps_ = bitrate_bps;
1221 bitrate_updated_ = true;
1222 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1223 }
1224 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1225 bool GetAndResetBitrateUpdated() {
1226 bool bitrate_updated = bitrate_updated_;
1227 bitrate_updated_ = false;
1228 return bitrate_updated;
1229 }
1230
1231 private:
1232 uint32_t last_bitrate_bps_;
1233 bool bitrate_updated_;
1234 };
1235
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001236 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001237
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001238 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1239 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1240 for (const auto& rtp_packet : stream.incoming_packets)
1241 incoming_rtp.insert(
1242 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001243 }
1244 }
1245
1246 SimulatedClock clock(0);
1247 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001248 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001249 // Is this intentional?
1250 ReceiveSideCongestionController rscc(&clock, &packet_router);
1251 // TODO(holmer): Log the call config and use that here instead.
1252 // static const uint32_t kDefaultStartBitrateBps = 300000;
1253 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1254
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001255 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1256 PointStyle::kHighlight);
1257 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001258
1259 RateStatistics acked_bitrate(250, 8000);
1260 int64_t last_update_us = 0;
1261 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001262 const RtpPacketType& packet = *kv.second;
1263 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1264 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1265 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001266 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001267 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001268 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001269 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001270 if (bitrate_bps) {
1271 uint32_t y = *bitrate_bps / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001272 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001273 acked_time_series.points.emplace_back(x, y);
1274 }
1275 if (packet_router.GetAndResetBitrateUpdated() ||
1276 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1277 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001278 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001279 time_series.points.emplace_back(x, y);
1280 last_update_us = clock.TimeInMicroseconds();
1281 }
1282 }
1283 // Add the data set to the plot.
1284 plot->AppendTimeSeries(std::move(time_series));
1285 plot->AppendTimeSeries(std::move(acked_time_series));
1286
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001287 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1288 kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001289 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1290 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001291}
1292
tereliuse34c19c2016-08-15 08:47:14 -07001293void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001294 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1295 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001296 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001297 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001298 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1299 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001300
stefana0a8ed72017-09-06 02:06:32 -07001301 int64_t prev_y = 0;
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001302 for (auto packet : GetNetworkTrace(parsed_log_)) {
1303 if (packet.arrival_time_ms == PacketFeedback::kNotReceived)
1304 continue;
1305 float x = ToCallTimeSec(1000 * packet.feedback_arrival_time_ms);
1306 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1307 late_feedback_series.points.emplace_back(x, prev_y);
1308 continue;
stefanc3de0332016-08-02 07:22:17 -07001309 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001310 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1311 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001312 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1313 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1314 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001315 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001316 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001317
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001318 // We assume that the base network delay (w/o queues) is equal to half
1319 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1320 // observed 1-ways delay and add half the minumum RTT.
1321 const int64_t estimated_clock_offset_ms =
1322 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001323 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001324 point.y -= estimated_clock_offset_ms;
stefana0a8ed72017-09-06 02:06:32 -07001325 for (TimeSeriesPoint& point : late_feedback_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001326 point.y -= estimated_clock_offset_ms;
1327
stefanc3de0332016-08-02 07:22:17 -07001328 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001329 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1330 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001331
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001332 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1333 kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001334 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001335 plot->SetTitle("Network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001336}
stefan08383272016-12-20 08:51:52 -08001337
Bjorn Terelius0295a962017-10-25 17:42:41 +02001338void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001339 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1340 const std::vector<LoggedRtpPacketOutgoing>& packets =
1341 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001342
1343 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001344 RTC_LOG(LS_WARNING)
1345 << "Can't estimate a the RTP clock frequency or the "
1346 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001347 continue;
1348 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001349 int64_t end_time_us = log_segments_.empty()
1350 ? std::numeric_limits<int64_t>::max()
1351 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001352 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001353 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001354 if (!estimated_frequency)
1355 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001356 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1357 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001358 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001359 << "Video stream should use a 90 kHz clock but appears to use "
1360 << *estimated_frequency / 1000 << ". Discarding.";
1361 continue;
1362 }
1363
1364 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001365 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001366 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001367 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001368 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1369 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001370 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1371 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1372 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001373 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001374 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001375 first_capture_timestamp) /
1376 *estimated_frequency * 1000;
1377 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001378 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1379 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001380 float x = ToCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001381 float y = send_time_ms - capture_time_ms;
1382 pacer_delay_series.points.emplace_back(x, y);
1383 }
1384 plot->AppendTimeSeries(std::move(pacer_delay_series));
1385 }
1386
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001387 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1388 kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001389 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1390 plot->SetTitle(
1391 "Delay from capture to send time. (First packet normalized to 0.)");
1392}
1393
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001394void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1395 Plot* plot) {
1396 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1397 TimeSeries rtp_timestamps(
1398 GetStreamName(direction, stream.ssrc) + " capture-time",
1399 LineStyle::kLine, PointStyle::kHighlight);
1400 for (const auto& packet : stream.packet_view) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001401 float x = ToCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001402 float y = packet.header.timestamp;
1403 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001404 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001405 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001406
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001407 TimeSeries rtcp_timestamps(
1408 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1409 LineStyle::kLine, PointStyle::kHighlight);
1410 // TODO(terelius): Why only sender reports?
1411 const auto& sender_reports = parsed_log_.sender_reports(direction);
1412 for (const auto& rtcp : sender_reports) {
1413 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1414 continue;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001415 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001416 float y = rtcp.sr.rtp_timestamp();
1417 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001418 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001419 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001420 }
1421
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001422 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1423 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001424 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1425 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001426}
michaelt6e5b2192017-02-22 07:33:27 -08001427
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001428void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1429 PacketDirection direction,
1430 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1431 std::string title,
1432 std::string yaxis_label,
1433 Plot* plot) {
1434 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1435 const auto& sender_reports = parsed_log_.sender_reports(direction);
1436 for (const auto& rtcp : sender_reports) {
1437 float x = ToCallTimeSec(rtcp.log_time_us());
1438 uint32_t ssrc = rtcp.sr.sender_ssrc();
1439 for (const auto& block : rtcp.sr.report_blocks()) {
1440 float y = fy(block);
1441 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1442 bool inserted;
1443 if (sr_report_it == sr_reports_by_ssrc.end()) {
1444 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1445 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1446 LineStyle::kLine, PointStyle::kHighlight));
1447 }
1448 sr_report_it->second.points.emplace_back(x, y);
1449 }
1450 }
1451 for (auto& kv : sr_reports_by_ssrc) {
1452 plot->AppendTimeSeries(std::move(kv.second));
1453 }
1454
1455 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1456 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1457 for (const auto& rtcp : receiver_reports) {
1458 float x = ToCallTimeSec(rtcp.log_time_us());
1459 uint32_t ssrc = rtcp.rr.sender_ssrc();
1460 for (const auto& block : rtcp.rr.report_blocks()) {
1461 float y = fy(block);
1462 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1463 bool inserted;
1464 if (rr_report_it == rr_reports_by_ssrc.end()) {
1465 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1466 ssrc,
1467 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1468 LineStyle::kLine, PointStyle::kHighlight));
1469 }
1470 rr_report_it->second.points.emplace_back(x, y);
1471 }
1472 }
1473 for (auto& kv : rr_reports_by_ssrc) {
1474 plot->AppendTimeSeries(std::move(kv.second));
1475 }
1476
1477 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1478 kLeftMargin, kRightMargin);
1479 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1480 plot->SetTitle(title);
1481}
1482
michaelt6e5b2192017-02-22 07:33:27 -08001483void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001484 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1485 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001486 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001487 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001488 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001489 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001490 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001491 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001492 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001493 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1494 return this->ToCallTimeSec(packet.log_time_us());
1495 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001496 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001497 ToCallTime, GetAnaBitrateBps,
1498 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001499 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001500 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1501 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001502 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1503 plot->SetTitle("Reported audio encoder target bitrate");
1504}
1505
1506void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001507 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1508 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001509 auto GetAnaFrameLengthMs =
1510 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001511 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001512 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001513 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001514 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001515 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001516 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1517 return this->ToCallTimeSec(packet.log_time_us());
1518 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001519 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001520 ToCallTime, GetAnaFrameLengthMs,
1521 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001522 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001523 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1524 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001525 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1526 plot->SetTitle("Reported audio encoder frame length");
1527}
1528
terelius2ee076d2017-08-15 02:04:02 -07001529void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001530 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001531 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001532 auto GetAnaPacketLoss =
1533 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001534 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001535 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001536 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001537 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001538 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001539 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1540 return this->ToCallTimeSec(packet.log_time_us());
1541 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001542 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001543 ToCallTime, GetAnaPacketLoss,
1544 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001545 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001546 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1547 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001548 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1549 kTopMargin);
1550 plot->SetTitle("Reported audio encoder lost packets");
1551}
1552
1553void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001554 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1555 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001556 auto GetAnaFecEnabled =
1557 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001558 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001559 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001560 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001561 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001562 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001563 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1564 return this->ToCallTimeSec(packet.log_time_us());
1565 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001566 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001567 ToCallTime, GetAnaFecEnabled,
1568 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001569 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001570 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1571 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001572 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1573 plot->SetTitle("Reported audio encoder FEC");
1574}
1575
1576void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001577 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1578 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001579 auto GetAnaDtxEnabled =
1580 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001581 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001582 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001583 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001584 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001585 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001586 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1587 return this->ToCallTimeSec(packet.log_time_us());
1588 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001589 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001590 ToCallTime, GetAnaDtxEnabled,
1591 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001592 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001593 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1594 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001595 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1596 plot->SetTitle("Reported audio encoder DTX");
1597}
1598
1599void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001600 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1601 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001602 auto GetAnaNumChannels =
1603 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001604 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001605 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001606 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001607 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001608 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001609 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1610 return this->ToCallTimeSec(packet.log_time_us());
1611 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001612 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001613 ToCallTime, GetAnaNumChannels,
1614 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001615 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001616 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1617 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001618 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1619 kBottomMargin, kTopMargin);
1620 plot->SetTitle("Reported audio encoder number of channels");
1621}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001622
1623class NetEqStreamInput : public test::NetEqInput {
1624 public:
1625 // Does not take any ownership, and all pointers must refer to valid objects
1626 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001627 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001628 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001629 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001630 : packet_stream_(*packet_stream),
1631 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001632 output_events_it_(output_events->begin()),
1633 output_events_end_(output_events->end()),
1634 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001635 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001636 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001637 }
1638
Danil Chapovalov431abd92018-06-18 12:54:17 +02001639 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001640 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001641 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001642 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001643 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001644 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001645 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001646 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001647 }
1648
Danil Chapovalov431abd92018-06-18 12:54:17 +02001649 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001650 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001651 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001652 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001653 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001654 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001655 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001656 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001657 }
1658
1659 std::unique_ptr<PacketData> PopPacket() override {
1660 if (packet_stream_it_ == packet_stream_.end()) {
1661 return std::unique_ptr<PacketData>();
1662 }
1663 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001664 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001665 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001666
1667 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1668 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001669 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1670 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001671 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1672
1673 ++packet_stream_it_;
1674 return packet_data;
1675 }
1676
1677 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001678 if (output_events_it_ != output_events_end_) {
1679 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001680 }
1681 }
1682
1683 bool ended() const override { return !NextEventTime(); }
1684
Danil Chapovalov431abd92018-06-18 12:54:17 +02001685 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001686 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001687 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001688 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001689 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001690 }
1691
1692 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001693 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1694 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001695 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1696 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001697 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001698};
1699
1700namespace {
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001701
1702// Factory to create a "replacement decoder" that produces the decoded audio
1703// by reading from a file rather than from the encoded payloads.
1704class ReplacementAudioDecoderFactory : public AudioDecoderFactory {
1705 public:
1706 ReplacementAudioDecoderFactory(const absl::string_view replacement_file_name,
1707 int file_sample_rate_hz)
1708 : replacement_file_name_(replacement_file_name),
1709 file_sample_rate_hz_(file_sample_rate_hz) {}
1710
1711 std::vector<AudioCodecSpec> GetSupportedDecoders() override {
1712 RTC_NOTREACHED();
1713 return {};
1714 }
1715
1716 bool IsSupportedDecoder(const SdpAudioFormat& format) override {
1717 return true;
1718 }
1719
1720 std::unique_ptr<AudioDecoder> MakeAudioDecoder(
1721 const SdpAudioFormat& format,
1722 absl::optional<AudioCodecPairId> codec_pair_id) override {
1723 auto replacement_file = absl::make_unique<test::ResampleInputAudioFile>(
1724 replacement_file_name_, file_sample_rate_hz_);
1725 replacement_file->set_output_rate_hz(48000);
1726 return absl::make_unique<test::FakeDecodeFromFile>(
1727 std::move(replacement_file), 48000, false);
1728 }
1729
1730 private:
1731 const std::string replacement_file_name_;
1732 const int file_sample_rate_hz_;
1733};
1734
henrik.lundin3c938fc2017-06-14 06:09:58 -07001735// Creates a NetEq test object and all necessary input and output helpers. Runs
1736// the test and returns the NetEqDelayAnalyzer object that was used to
1737// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001738std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001739 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001740 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001741 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001742 const std::string& replacement_file_name,
1743 int file_sample_rate_hz) {
1744 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001745 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001746
1747 constexpr int kReplacementPt = 127;
1748 std::set<uint8_t> cn_types;
1749 std::set<uint8_t> forbidden_types;
1750 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1751 cn_types, forbidden_types));
1752
1753 NetEq::Config config;
1754 config.max_packets_in_buffer = 200;
1755 config.enable_fast_accelerate = true;
1756
1757 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1758
Niels Möller3f651d82018-12-19 15:06:17 +01001759 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
Bjorn Terelius6c4b1b72019-01-11 13:01:29 +01001760 new rtc::RefCountedObject<ReplacementAudioDecoderFactory>(
1761 replacement_file_name, file_sample_rate_hz);
Niels Möller3f651d82018-12-19 15:06:17 +01001762
Niels Möller05543682019-01-10 16:55:06 +01001763 test::NetEqTest::DecoderMap codecs = {
1764 {kReplacementPt, SdpAudioFormat("l16", 48000, 1)}};
henrik.lundin3c938fc2017-06-14 06:09:58 -07001765
1766 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1767 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001768 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1769 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001770 test::DefaultNetEqTestErrorCallback error_cb;
1771 test::NetEqTest::Callbacks callbacks;
1772 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001773 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1774 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001775
Niels Möllerbd6dee82019-01-02 09:39:47 +01001776 test::NetEqTest test(config, decoder_factory, codecs, nullptr,
Niels Möller3f651d82018-12-19 15:06:17 +01001777 std::move(input), std::move(output), callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001778 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001779 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001780}
1781} // namespace
1782
Minyue Lic6ff7572018-05-04 09:46:44 +02001783EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001784 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001785 int file_sample_rate_hz) const {
1786 NetEqStatsGetterMap neteq_stats;
1787
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001788 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001789 const uint32_t ssrc = stream.ssrc;
1790 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1791 continue;
1792 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1793 &stream.incoming_packets;
1794 if (audio_packets == nullptr) {
1795 // No incoming audio stream found.
1796 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001797 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001798
Minyue Li27e2b7d2018-05-07 15:20:24 +02001799 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1800
1801 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1802 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1803 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1804 // Could not find output events with SSRC matching the input audio stream.
1805 // Using the first available stream of output events.
1806 output_events_it = parsed_log_.audio_playout_events().cbegin();
1807 }
1808
Danil Chapovalov431abd92018-06-18 12:54:17 +02001809 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001810 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001811 ? absl::nullopt
1812 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001813
1814 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1815 audio_packets, &output_events_it->second, end_time_ms,
1816 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001817 }
1818
Minyue Lic6ff7572018-05-04 09:46:44 +02001819 return neteq_stats;
1820}
1821
Minyue Lic97933f2018-08-10 12:51:15 +02001822// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1823// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001824void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001825 uint32_t ssrc,
1826 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001827 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001828 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1829 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1830 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1831 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1832
Minyue Li01d2a672018-06-21 21:17:19 +02001833 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001834 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1835 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001836
Minyue Lic97933f2018-08-10 12:51:15 +02001837 TimeSeries time_series_packet_arrival("packet arrival delay",
1838 LineStyle::kLine);
1839 TimeSeries time_series_relative_packet_arrival(
1840 "Relative packet arrival delay", LineStyle::kLine);
1841 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
1842 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
1843 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02001844
1845 for (const auto& data : arrival_delay_ms) {
1846 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1847 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001848 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001849 }
1850 for (const auto& data : corrected_arrival_delay_ms) {
1851 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1852 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001853 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02001854 TimeSeriesPoint(x, y));
1855 }
1856 for (const auto& data : playout_delay_ms) {
1857 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1858 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001859 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001860 }
1861 for (const auto& data : target_delay_ms) {
1862 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1863 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001864 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001865 }
1866
Minyue Lic97933f2018-08-10 12:51:15 +02001867 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
1868 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
1869 plot->AppendTimeSeries(std::move(time_series_play_time));
1870 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001871
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001872 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1873 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001874 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
1875 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001876 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
1877}
1878
Minyue Lic9ac93f2018-06-26 13:01:32 +02001879template <typename NetEqStatsType>
1880void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001881 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02001882 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
1883 const test::NetEqStatsGetter*)> data_extractor,
1884 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001885 const std::string& plot_name,
1886 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001887 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001888
1889 for (const auto& st : neteq_stats) {
1890 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02001891 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
1892 data_extractor(st.second.get());
1893 for (const auto& data : *data_vector) {
1894 const float time = ToCallTimeSec(data.first * 1000); // ms to us.
1895 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001896 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02001897 }
1898 }
1899
1900 for (auto& series : time_series) {
1901 series.second.label = GetStreamName(kIncomingPacket, series.first);
1902 series.second.line_style = LineStyle::kLine;
1903 plot->AppendTimeSeries(std::move(series.second));
1904 }
1905
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001906 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1907 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001908 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001909 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001910}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001911
Minyue Lic9ac93f2018-06-26 13:01:32 +02001912void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
1913 const NetEqStatsGetterMap& neteq_stats,
1914 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
1915 const std::string& plot_name,
1916 Plot* plot) const {
1917 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
1918 neteq_stats,
1919 [](const test::NetEqStatsGetter* stats_getter) {
1920 return stats_getter->stats();
1921 },
1922 stats_extractor, plot_name, plot);
1923}
1924
1925void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
1926 const NetEqStatsGetterMap& neteq_stats,
1927 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
1928 const std::string& plot_name,
1929 Plot* plot) const {
1930 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
1931 neteq_stats,
1932 [](const test::NetEqStatsGetter* stats_getter) {
1933 return stats_getter->lifetime_stats();
1934 },
1935 stats_extractor, plot_name, plot);
1936}
1937
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001938void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1939 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001940 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001941 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1942 configs_by_cp_id.end()) {
1943 const std::string candidate_pair_desc =
1944 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001945 configs_by_cp_id[config.candidate_pair_id] =
1946 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1947 candidate_pair_desc,
1948 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001949 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1950 candidate_pair_desc;
1951 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001952 float x = ToCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001953 float y = static_cast<float>(config.type);
1954 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1955 }
1956
1957 // TODO(qingsi): There can be a large number of candidate pairs generated by
1958 // certain calls and the frontend cannot render the chart in this case due to
1959 // the failure of generating a palette with the same number of colors.
1960 for (auto& kv : configs_by_cp_id) {
1961 plot->AppendTimeSeries(std::move(kv.second));
1962 }
1963
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001964 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1965 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001966 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
1967 kTopMargin);
1968 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1969}
1970
1971std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1972 uint32_t candidate_pair_id) {
1973 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1974 candidate_pair_desc_by_id_.end()) {
1975 return candidate_pair_desc_by_id_[candidate_pair_id];
1976 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001977 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001978 // TODO(qingsi): Add the handling of the "Updated" config event after the
1979 // visualization of property change for candidate pairs is introduced.
1980 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1981 candidate_pair_desc_by_id_.end()) {
1982 const std::string candidate_pair_desc =
1983 GetCandidatePairLogDescriptionAsString(config);
1984 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1985 candidate_pair_desc;
1986 }
1987 }
1988 return candidate_pair_desc_by_id_[candidate_pair_id];
1989}
1990
1991void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1992 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001993 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001994 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1995 checks_by_cp_id.end()) {
1996 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08001997 "[" + std::to_string(event.candidate_pair_id) + "]" +
1998 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001999 LineStyle::kNone, PointStyle::kHighlight);
2000 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002001 float x = ToCallTimeSec(event.log_time_us());
Zach Stein6353fbc2018-12-03 14:35:59 -08002002 constexpr int kIceCandidatePairEventTypeOffset =
2003 static_cast<int>(IceCandidatePairConfigType::kNumValues);
2004 float y = static_cast<float>(event.type) + kIceCandidatePairEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002005 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2006 }
2007
2008 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2009 for (auto& kv : checks_by_cp_id) {
2010 plot->AppendTimeSeries(std::move(kv.second));
2011 }
2012
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002013 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
2014 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002015 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
2016 kTopMargin);
2017 plot->SetTitle("[IceEventLog] ICE connectivity checks");
2018}
2019
Zach Stein10a58012018-12-07 12:26:28 -08002020void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
2021 TimeSeries states("DTLS Transport State", LineStyle::kNone,
2022 PointStyle::kHighlight);
2023 for (const auto& event : parsed_log_.dtls_transport_states()) {
2024 float x = ToCallTimeSec(event.log_time_us());
2025 float y = static_cast<float>(event.dtls_transport_state);
2026 states.points.emplace_back(x, y);
2027 }
2028 plot->AppendTimeSeries(std::move(states));
2029 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
2030 kLeftMargin, kRightMargin);
2031 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
2032 "Numeric Transport State", kBottomMargin, kTopMargin);
2033 plot->SetTitle("DTLS Transport State");
2034}
2035
2036void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2037 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2038 PointStyle::kHighlight);
2039 for (const auto& event : parsed_log_.dtls_writable_states()) {
2040 float x = ToCallTimeSec(event.log_time_us());
2041 float y = static_cast<float>(event.writable);
2042 writable.points.emplace_back(x, y);
2043 }
2044 plot->AppendTimeSeries(std::move(writable));
2045 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
2046 kLeftMargin, kRightMargin);
2047 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2048 plot->SetTitle("DTLS Writable State");
2049}
2050
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002051void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002052 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002053 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2054 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2055 }
2056 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2057 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2058 }
2059 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2060 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2061 }
2062 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2063 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2064 }
2065 for (const auto& alert : incoming_seq_num_jumps_) {
2066 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2067 }
2068 for (const auto& alert : incoming_capture_time_jumps_) {
2069 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2070 }
2071 for (const auto& alert : outgoing_seq_num_jumps_) {
2072 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2073 }
2074 for (const auto& alert : outgoing_capture_time_jumps_) {
2075 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2076 }
2077 for (const auto& alert : outgoing_high_loss_alerts_) {
2078 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002079 }
2080 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2081}
2082
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002083void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2084 // With 100 packets/s (~800kbps), false positives would require 10 s without
2085 // data.
2086 constexpr int64_t kMaxSeqNumJump = 1000;
2087 // With a 90 kHz clock, false positives would require 10 s without data.
2088 constexpr int64_t kMaxCaptureTimeJump = 900000;
2089
2090 int64_t end_time_us = log_segments_.empty()
2091 ? std::numeric_limits<int64_t>::max()
2092 : log_segments_.front().second;
2093
2094 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002095 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002096 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002097 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002098 // Check for gaps in sequence numbers and capture timestamps.
2099 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2100 for (const auto& packet : stream.packet_view) {
2101 if (packet.log_time_us() > end_time_us) {
2102 // Only process the first (LOG_START, LOG_END) segment.
2103 break;
2104 }
2105
2106 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2107 if (last_seq_num.has_value() &&
2108 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002109 Alert_SeqNumJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002110 packet.header.ssrc);
2111 }
2112 last_seq_num.emplace(seq_num);
2113
2114 int64_t capture_time =
2115 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2116 if (last_capture_time.has_value() &&
2117 std::abs(capture_time - last_capture_time.value()) >
2118 kMaxCaptureTimeJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002119 Alert_CaptureTimeJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002120 packet.header.ssrc);
2121 }
2122 last_capture_time.emplace(capture_time);
2123 }
2124 }
2125}
2126
2127void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2128 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2129 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2130 int64_t end_time_us = log_segments_.empty()
2131 ? std::numeric_limits<int64_t>::max()
2132 : log_segments_.front().second;
2133
2134 // TODO(terelius): The parser could provide a list of all packets, ordered
2135 // by time, for each direction.
2136 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2137 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2138 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2139 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2140 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002141 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002142 for (const auto& kv : rtp_in_direction) {
2143 int64_t timestamp = kv.first;
2144 if (timestamp > end_time_us) {
2145 // Only process the first (LOG_START, LOG_END) segment.
2146 break;
2147 }
2148 int64_t duration = timestamp - last_rtp_time.value_or(0);
2149 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2150 // No packet sent/received for more than 500 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002151 Alert_RtpLogTimeGap(direction, ToCallTimeSec(timestamp), duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002152 }
2153 last_rtp_time.emplace(timestamp);
2154 }
2155
Danil Chapovalov431abd92018-06-18 12:54:17 +02002156 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002157 if (direction == kIncomingPacket) {
2158 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2159 if (rtcp.log_time_us() > end_time_us) {
2160 // Only process the first (LOG_START, LOG_END) segment.
2161 break;
2162 }
2163 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2164 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2165 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002166 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002167 duration / 1000);
2168 }
2169 last_rtcp_time.emplace(rtcp.log_time_us());
2170 }
2171 } else {
2172 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2173 if (rtcp.log_time_us() > end_time_us) {
2174 // Only process the first (LOG_START, LOG_END) segment.
2175 break;
2176 }
2177 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2178 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2179 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002180 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002181 duration / 1000);
2182 }
2183 last_rtcp_time.emplace(rtcp.log_time_us());
2184 }
2185 }
2186}
2187
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002188// TODO(terelius): Notifications could possibly be generated by the same code
2189// that produces the graphs. There is some code duplication that could be
2190// avoided, but that might be solved anyway when we move functionality from the
2191// analyzer to the parser.
2192void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002193 CreateStreamGapAlerts(kIncomingPacket);
2194 CreateStreamGapAlerts(kOutgoingPacket);
2195 CreateTransmissionGapAlerts(kIncomingPacket);
2196 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002197
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002198 int64_t end_time_us = log_segments_.empty()
2199 ? std::numeric_limits<int64_t>::max()
2200 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002201
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002202 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002203 // Loss feedback
2204 int64_t total_lost_packets = 0;
2205 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002206 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2207 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002208 // Only process the first (LOG_START, LOG_END) segment.
2209 break;
2210 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002211 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002212 bwe_update.expected_packets;
2213 total_lost_packets += lost_packets;
2214 total_expected_packets += bwe_update.expected_packets;
2215 }
2216 double avg_outgoing_loss =
2217 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002218 if (avg_outgoing_loss > kMaxLossFraction) {
2219 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002220 }
2221}
2222
terelius54ce6802016-07-13 06:44:41 -07002223} // namespace webrtc