blob: cae810c18540140909e11a020c38308013989cc0 [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"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020021#include "api/transport/goog_cc_factory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020022#include "call/audio_receive_stream.h"
23#include "call/audio_send_stream.h"
24#include "call/call.h"
25#include "call/video_receive_stream.h"
26#include "call/video_send_stream.h"
Mirko Bonadei71207422017-09-15 13:58:09 +020027#include "common_types.h" // NOLINT(build/include)
Elad Alon99a81b62017-09-21 10:25:29 +020028#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020029#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020030#include "modules/audio_coding/neteq/tools/audio_sink.h"
31#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
32#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
33#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
34#include "modules/audio_coding/neteq/tools/neteq_test.h"
35#include "modules/audio_coding/neteq/tools/resample_input_audio_file.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020036#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
37#include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020038#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020039#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020040#include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010041#include "modules/pacing/packet_router.h"
Sebastian Jansson5c94f552018-10-15 18:46:51 +020042#include "modules/remote_bitrate_estimator/include/bwe_defines.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020043#include "modules/rtp_rtcp/include/rtp_rtcp.h"
44#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020045#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020046#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
47#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
48#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
49#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
50#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
51#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
52#include "modules/rtp_rtcp/source/rtp_utility.h"
53#include "rtc_base/checks.h"
54#include "rtc_base/format_macros.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020055#include "rtc_base/function_view.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020056#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020057#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020058#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020059#include "rtc_base/strings/string_builder.h"
Niels Möllerdaa970f2018-12-17 09:33:55 +010060#include "test/function_audio_decoder_factory.h"
terelius54ce6802016-07-13 06:44:41 -070061
Bjorn Terelius6984ad22017-10-24 12:19:45 +020062#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
63#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
64#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
65
tereliusdc35dcd2016-08-01 12:03:27 -070066namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070067
terelius54ce6802016-07-13 06:44:41 -070068namespace {
69
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080070const int kNumMicrosecsPerSec = 1000000;
71
elad.alonec304f92017-03-08 05:03:53 -080072void SortPacketFeedbackVector(std::vector<PacketFeedback>* vec) {
73 auto pred = [](const PacketFeedback& packet_feedback) {
74 return packet_feedback.arrival_time_ms == PacketFeedback::kNotReceived;
75 };
76 vec->erase(std::remove_if(vec->begin(), vec->end(), pred), vec->end());
77 std::sort(vec->begin(), vec->end(), PacketFeedbackComparator());
78}
79
terelius54ce6802016-07-13 06:44:41 -070080std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020081 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070082 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020083 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070084}
85
86// Checks whether an SSRC is contained in the list of desired SSRCs.
87// Note that an empty SSRC list matches every SSRC.
88bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
89 if (desired_ssrc.size() == 0)
90 return true;
91 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
92 desired_ssrc.end();
93}
94
95double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
96 // The timestamp is a fixed point representation with 6 bits for seconds
97 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080098 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
99 // microseconds.
terelius54ce6802016-07-13 06:44:41 -0700100 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800101 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -0700102 return abs_send_time * kTimestampToMicroSec;
103}
104
105// Computes the difference |later| - |earlier| where |later| and |earlier|
106// are counters that wrap at |modulus|. The difference is chosen to have the
107// least absolute value. For example if |modulus| is 8, then the difference will
108// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
109// be in [-4, 4].
110int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
111 RTC_DCHECK_LE(1, modulus);
112 RTC_DCHECK_LT(later, modulus);
113 RTC_DCHECK_LT(earlier, modulus);
114 int64_t difference =
115 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
116 int64_t max_difference = modulus / 2;
117 int64_t min_difference = max_difference - modulus + 1;
118 if (difference > max_difference) {
119 difference -= modulus;
120 }
121 if (difference < min_difference) {
122 difference += modulus;
123 }
terelius6addf492016-08-23 17:34:07 -0700124 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100125 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
126 << " expected to be in the range ("
127 << min_difference / 2 << "," << max_difference / 2
128 << ") but is " << difference
129 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700130 }
terelius54ce6802016-07-13 06:44:41 -0700131 return difference;
132}
133
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200134// This is much more reliable for outgoing streams than for incoming streams.
135template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200136absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200137 const RtpPacketContainer& packets,
138 int64_t end_time_us) {
139 RTC_CHECK(packets.size() >= 2);
140 SeqNumUnwrapper<uint32_t> unwrapper;
141 uint64_t first_rtp_timestamp =
142 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
143 int64_t first_log_timestamp = packets[0].log_time_us();
144 uint64_t last_rtp_timestamp = first_rtp_timestamp;
145 int64_t last_log_timestamp = first_log_timestamp;
146 for (size_t i = 1; i < packets.size(); i++) {
147 if (packets[i].log_time_us() > end_time_us)
148 break;
149 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
150 last_log_timestamp = packets[i].log_time_us();
151 }
152 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
153 RTC_LOG(LS_WARNING)
154 << "Failed to estimate RTP clock frequency: Stream too short. ("
155 << packets.size() << " packets, "
156 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200157 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200158 }
159 double duration =
160 static_cast<double>(last_log_timestamp - first_log_timestamp) /
161 kNumMicrosecsPerSec;
162 double estimated_frequency =
163 (last_rtp_timestamp - first_rtp_timestamp) / duration;
164 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
165 if (std::fabs(estimated_frequency - f) < 0.05 * f) {
166 return f;
167 }
168 }
169 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
170 << estimated_frequency
171 << "not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200172 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700173}
174
tereliusdc35dcd2016-08-01 12:03:27 -0700175constexpr float kLeftMargin = 0.01f;
176constexpr float kRightMargin = 0.02f;
177constexpr float kBottomMargin = 0.02f;
178constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700179
Danil Chapovalov431abd92018-06-18 12:54:17 +0200180absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100181 const LoggedRtpPacketIncoming& old_packet,
182 const LoggedRtpPacketIncoming& new_packet) {
183 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
184 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700185 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100186 new_packet.rtp.header.extension.absoluteSendTime,
187 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200188 int64_t recv_time_diff =
189 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700190 double delay_change_us =
191 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100192 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700193 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200194 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700195 }
196}
197
Danil Chapovalov431abd92018-06-18 12:54:17 +0200198absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100199 const LoggedRtpPacketIncoming& old_packet,
200 const LoggedRtpPacketIncoming& new_packet,
201 const double sample_rate) {
202 int64_t send_time_diff =
203 WrappingDifference(new_packet.rtp.header.timestamp,
204 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200205 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700206
terelius53dc23c2017-03-13 05:24:05 -0700207 double delay_change =
208 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100209 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700210 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100211 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100212 RTC_LOG(LS_WARNING) << "Old capture time "
213 << old_packet.rtp.header.timestamp << ", received time "
214 << old_packet.log_time_us();
215 RTC_LOG(LS_WARNING) << "New capture time "
216 << new_packet.rtp.header.timestamp << ", received time "
217 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100218 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800219 << static_cast<double>(recv_time_diff) /
220 kNumMicrosecsPerSec
221 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100222 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100223 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100224 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700225 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100226 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700227}
228
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200229// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700230// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200231template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200232void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200233 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200234 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200235 TimeSeries* result) {
236 for (size_t i = 0; i < data_view.size(); i++) {
237 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200238 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200239 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700240 if (y)
241 result->points.emplace_back(x, *y);
242 }
243}
244
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200245// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700246// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
247// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200248template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700249void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200250 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200251 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
252 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200253 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700254 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700255 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200256 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200257 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700258 if (y)
259 result->points.emplace_back(x, static_cast<float>(*y));
260 }
261}
262
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200263// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700264// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
265// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200266template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700267void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200268 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200269 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
270 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200271 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700272 TimeSeries* result) {
273 ResultType sum = 0;
274 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200275 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200276 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100277 if (y) {
terelius53dc23c2017-03-13 05:24:05 -0700278 sum += *y;
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100279 result->points.emplace_back(x, static_cast<float>(sum));
280 }
tereliusccbbf8d2016-08-10 07:34:28 -0700281 }
282}
283
terelius6addf492016-08-23 17:34:07 -0700284// Calculates a moving average of |data| and stores the result in a TimeSeries.
285// A data point is generated every |step| microseconds from |begin_time|
286// to |end_time|. The value of each data point is the average of the data
287// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200288template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700289void MovingAverage(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200290 rtc::FunctionView<float(int64_t)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200291 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200292 const IterableType& data_view,
293 int64_t begin_time,
294 int64_t end_time,
295 int64_t window_duration_us,
296 int64_t step,
297 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700298 size_t window_index_begin = 0;
299 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700300 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700301
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200302 for (int64_t t = begin_time; t < end_time + step; t += step) {
303 while (window_index_end < data_view.size() &&
304 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200305 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700306 if (value)
307 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700308 ++window_index_end;
309 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200310 while (window_index_begin < data_view.size() &&
311 data_view[window_index_begin].log_time_us() <
312 t - window_duration_us) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200313 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700314 if (value)
315 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700316 ++window_index_begin;
317 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800318 float window_duration_s =
319 static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200320 float x = fx(t);
terelius53dc23c2017-03-13 05:24:05 -0700321 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700322 result->points.emplace_back(x, y);
323 }
324}
325
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800326const char kUnknownEnumValue[] = "unknown";
327
328const char kIceCandidateTypeLocal[] = "local";
329const char kIceCandidateTypeStun[] = "stun";
330const char kIceCandidateTypePrflx[] = "prflx";
331const char kIceCandidateTypeRelay[] = "relay";
332
333const char kProtocolUdp[] = "udp";
334const char kProtocolTcp[] = "tcp";
335const char kProtocolSsltcp[] = "ssltcp";
336const char kProtocolTls[] = "tls";
337
338const char kAddressFamilyIpv4[] = "ipv4";
339const char kAddressFamilyIpv6[] = "ipv6";
340
341const char kNetworkTypeEthernet[] = "ethernet";
342const char kNetworkTypeLoopback[] = "loopback";
343const char kNetworkTypeWifi[] = "wifi";
344const char kNetworkTypeVpn[] = "vpn";
345const char kNetworkTypeCellular[] = "cellular";
346
347std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
348 switch (type) {
349 case webrtc::IceCandidateType::kLocal:
350 return kIceCandidateTypeLocal;
351 case webrtc::IceCandidateType::kStun:
352 return kIceCandidateTypeStun;
353 case webrtc::IceCandidateType::kPrflx:
354 return kIceCandidateTypePrflx;
355 case webrtc::IceCandidateType::kRelay:
356 return kIceCandidateTypeRelay;
357 default:
358 return kUnknownEnumValue;
359 }
360}
361
362std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
363 switch (protocol) {
364 case webrtc::IceCandidatePairProtocol::kUdp:
365 return kProtocolUdp;
366 case webrtc::IceCandidatePairProtocol::kTcp:
367 return kProtocolTcp;
368 case webrtc::IceCandidatePairProtocol::kSsltcp:
369 return kProtocolSsltcp;
370 case webrtc::IceCandidatePairProtocol::kTls:
371 return kProtocolTls;
372 default:
373 return kUnknownEnumValue;
374 }
375}
376
377std::string GetAddressFamilyAsString(
378 webrtc::IceCandidatePairAddressFamily family) {
379 switch (family) {
380 case webrtc::IceCandidatePairAddressFamily::kIpv4:
381 return kAddressFamilyIpv4;
382 case webrtc::IceCandidatePairAddressFamily::kIpv6:
383 return kAddressFamilyIpv6;
384 default:
385 return kUnknownEnumValue;
386 }
387}
388
389std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
390 switch (type) {
391 case webrtc::IceCandidateNetworkType::kEthernet:
392 return kNetworkTypeEthernet;
393 case webrtc::IceCandidateNetworkType::kLoopback:
394 return kNetworkTypeLoopback;
395 case webrtc::IceCandidateNetworkType::kWifi:
396 return kNetworkTypeWifi;
397 case webrtc::IceCandidateNetworkType::kVpn:
398 return kNetworkTypeVpn;
399 case webrtc::IceCandidateNetworkType::kCellular:
400 return kNetworkTypeCellular;
401 default:
402 return kUnknownEnumValue;
403 }
404}
405
406std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200407 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800408 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
409 // represents a pair of a local server-reflexive candidate on a WiFi network
410 // and a remote relay candidate using TCP as the relay protocol on a cell
411 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200412 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800413 std::string local_candidate_type =
414 GetIceCandidateTypeAsString(config.local_candidate_type);
415 std::string remote_candidate_type =
416 GetIceCandidateTypeAsString(config.remote_candidate_type);
417 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
418 local_candidate_type +=
419 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
420 }
421 ss << local_candidate_type << ":"
422 << GetNetworkTypeAsString(config.local_network_type) << ":"
423 << GetAddressFamilyAsString(config.local_address_family) << "->"
424 << remote_candidate_type << ":"
425 << GetAddressFamilyAsString(config.remote_address_family) << "@"
426 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200427 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800428}
429
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200430std::string GetDirectionAsString(PacketDirection direction) {
431 if (direction == kIncomingPacket) {
432 return "Incoming";
433 } else {
434 return "Outgoing";
435 }
436}
437
438std::string GetDirectionAsShortString(PacketDirection direction) {
439 if (direction == kIncomingPacket) {
440 return "In";
441 } else {
442 return "Out";
443 }
444}
445
terelius54ce6802016-07-13 06:44:41 -0700446} // namespace
447
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200448EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log,
449 bool normalize_time)
450 : parsed_log_(log),
451 window_duration_(250000),
452 step_(10000),
453 normalize_time_(normalize_time) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200454 begin_time_ = parsed_log_.first_timestamp();
455 end_time_ = parsed_log_.last_timestamp();
456 if (end_time_ < begin_time_) {
457 RTC_LOG(LS_WARNING) << "No useful events in the log.";
458 begin_time_ = end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000459 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200460 call_duration_s_ = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200461
462 const auto& log_start_events = parsed_log_.start_log_events();
463 const auto& log_end_events = parsed_log_.stop_log_events();
464 auto start_iter = log_start_events.begin();
465 auto end_iter = log_end_events.begin();
466 while (start_iter != log_start_events.end()) {
467 int64_t start = start_iter->log_time_us();
468 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200469 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200470 if (start_iter != log_start_events.end())
471 next_start.emplace(start_iter->log_time_us());
472 if (end_iter != log_end_events.end() &&
473 end_iter->log_time_us() <=
474 next_start.value_or(std::numeric_limits<int64_t>::max())) {
475 int64_t end = end_iter->log_time_us();
476 RTC_DCHECK_LE(start, end);
477 log_segments_.push_back(std::make_pair(start, end));
478 ++end_iter;
479 } else {
480 // we're missing an end event. Assume that it occurred just before the
481 // next start.
482 log_segments_.push_back(
483 std::make_pair(start, next_start.value_or(end_time_)));
484 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700485 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100486 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200487 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700488}
489
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200490class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200491 public:
492 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
493
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200494 void Update(NetworkControlUpdate update) {
495 if (update.target_rate) {
496 last_bitrate_bps_ = update.target_rate->target_rate.bps();
497 bitrate_updated_ = true;
498 }
Stefan Holmer13181032016-07-29 14:48:54 +0200499 }
500
501 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
502 uint32_t bitrate) override {}
503
504 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
505 bool GetAndResetBitrateUpdated() {
506 bool bitrate_updated = bitrate_updated_;
507 bitrate_updated_ = false;
508 return bitrate_updated;
509 }
510
511 private:
512 uint32_t last_bitrate_bps_;
513 bool bitrate_updated_;
514};
515
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200516int64_t EventLogAnalyzer::ToCallTimeUs(int64_t timestamp) const {
517 int64_t begin_time = 0;
518 if (normalize_time_) {
519 begin_time = begin_time_;
520 }
521 return timestamp - begin_time;
522}
523
524float EventLogAnalyzer::ToCallTimeSec(int64_t timestamp) const {
525 return static_cast<float>(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100526}
527
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200528void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700529 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200530 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
531 // Filter on SSRC.
532 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700533 continue;
terelius54ce6802016-07-13 06:44:41 -0700534 }
terelius54ce6802016-07-13 06:44:41 -0700535
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200536 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
537 LineStyle::kBar);
538 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200539 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200540 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200541 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
542 return this->ToCallTimeSec(packet.log_time_us());
543 };
544 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
545 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700546 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700547 }
548
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200549 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
550 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700551 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
552 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200553 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700554}
555
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200556template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700557void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700558 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200559 const IterableType& packets,
560 const std::string& label) {
561 TimeSeries time_series(label, LineStyle::kStep);
562 for (size_t i = 0; i < packets.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200563 float x = ToCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200564 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700565 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200566 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700567}
568
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200569void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
570 Plot* plot) {
571 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
572 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
573 continue;
574 std::string label =
575 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
576 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
577 }
578 std::string label =
579 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
580 if (direction == kIncomingPacket) {
581 CreateAccumulatedPacketsTimeSeries(
582 plot, parsed_log_.incoming_rtcp_packets(), label);
583 } else {
584 CreateAccumulatedPacketsTimeSeries(
585 plot, parsed_log_.outgoing_rtcp_packets(), label);
586 }
philipelccd74892016-09-05 02:46:25 -0700587
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200588 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
589 kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700590 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200591 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
592 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700593}
594
terelius54ce6802016-07-13 06:44:41 -0700595// For each SSRC, plot the time between the consecutive playouts.
596void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200597 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
598 uint32_t ssrc = playout_stream.first;
599 if (!MatchingSsrc(ssrc, desired_ssrc_))
600 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200601 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200602 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200603 for (const auto& playout_event : playout_stream.second) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200604 float x = ToCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200605 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200606 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200607 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200608 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200609 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700610 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200611 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700612 }
613
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200614 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
615 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700616 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
617 kTopMargin);
618 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700619}
620
ivocaac9d6f2016-09-22 07:01:47 -0700621// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200622void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
623 Plot* plot) {
624 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
625 if (!IsAudioSsrc(direction, stream.ssrc))
626 continue;
627 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
628 LineStyle::kLine);
629 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700630 if (packet.header.extension.hasAudioLevel) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200631 float x = ToCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700632 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
633 // Here we convert it to dBov.
634 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200635 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700636 }
637 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200638 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700639 }
640
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200641 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
642 kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200643 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200644 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700645}
646
terelius54ce6802016-07-13 06:44:41 -0700647// For each SSRC, plot the time between the consecutive playouts.
648void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200649 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
650 // Filter on SSRC.
651 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700652 continue;
terelius54ce6802016-07-13 06:44:41 -0700653 }
terelius54ce6802016-07-13 06:44:41 -0700654
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200655 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
656 LineStyle::kBar);
657 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
658 const LoggedRtpPacketIncoming& new_packet) {
659 int64_t diff =
660 WrappingDifference(new_packet.rtp.header.sequenceNumber,
661 old_packet.rtp.header.sequenceNumber, 1ul << 16);
662 return diff;
663 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200664 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
665 return this->ToCallTimeSec(packet.log_time_us());
666 };
667 ProcessPairs<LoggedRtpPacketIncoming, float>(
668 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
669 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700670 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700671 }
672
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200673 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
674 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700675 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
676 kTopMargin);
677 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700678}
679
Stefan Holmer99f8e082016-09-09 13:37:50 +0200680void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200681 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
682 const std::vector<LoggedRtpPacketIncoming>& packets =
683 stream.incoming_packets;
684 // Filter on SSRC.
685 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200686 continue;
687 }
688
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200689 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
690 LineStyle::kLine, PointStyle::kHighlight);
691 // TODO(terelius): Should the window and step size be read from the class
692 // instead?
693 const int64_t kWindowUs = 1000000;
694 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100695 SeqNumUnwrapper<uint16_t> unwrapper_;
696 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800697 size_t window_index_begin = 0;
698 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200699 uint64_t highest_seq_number =
700 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
701 uint64_t highest_prior_seq_number =
702 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800703
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200704 for (int64_t t = begin_time_; t < end_time_ + kStep; t += kStep) {
705 while (window_index_end < packets.size() &&
706 packets[window_index_end].rtp.log_time_us() < t) {
707 uint64_t sequence_number = unwrapper_.Unwrap(
708 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800709 highest_seq_number = std::max(highest_seq_number, sequence_number);
710 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200711 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200712 while (window_index_begin < packets.size() &&
713 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
714 uint64_t sequence_number = prior_unwrapper_.Unwrap(
715 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800716 highest_prior_seq_number =
717 std::max(highest_prior_seq_number, sequence_number);
718 ++window_index_begin;
719 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200720 float x = ToCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200721 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800722 if (expected_packets > 0) {
723 int64_t received_packets = window_index_end - window_index_begin;
724 int64_t lost_packets = expected_packets - received_packets;
725 float y = static_cast<float>(lost_packets) / expected_packets * 100;
726 time_series.points.emplace_back(x, y);
727 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200728 }
philipel35ba9bd2017-04-19 05:58:51 -0700729 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200730 }
731
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200732 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
733 kLeftMargin, kRightMargin);
Stefan Holmer99f8e082016-09-09 13:37:50 +0200734 plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
735 kTopMargin);
736 plot->SetTitle("Estimated incoming loss rate");
737}
738
terelius2ee076d2017-08-15 02:04:02 -0700739void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100740 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200741 // Filter on SSRC.
742 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200743 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700744 continue;
745 }
terelius54ce6802016-07-13 06:44:41 -0700746
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100747 const std::vector<LoggedRtpPacketIncoming>& packets =
748 stream.incoming_packets;
749 if (packets.size() < 100) {
750 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
751 << packets.size() << " packets in the stream.";
752 continue;
753 }
754 int64_t end_time_us = log_segments_.empty()
755 ? std::numeric_limits<int64_t>::max()
756 : log_segments_.front().second;
757 absl::optional<uint32_t> estimated_frequency =
758 EstimateRtpClockFrequency(packets, end_time_us);
759 if (!estimated_frequency)
760 continue;
761 const double frequency_hz = *estimated_frequency;
762 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
763 RTC_LOG(LS_WARNING)
764 << "Video stream should use a 90 kHz clock but appears to use "
765 << frequency_hz / 1000 << ". Discarding.";
766 continue;
767 }
768
769 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
770 return this->ToCallTimeSec(packet.log_time_us());
771 };
772 auto ToNetworkDelay = [frequency_hz](
773 const LoggedRtpPacketIncoming& old_packet,
774 const LoggedRtpPacketIncoming& new_packet) {
775 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
776 };
777
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200778 TimeSeries capture_time_data(
779 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
780 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100781 AccumulatePairs<LoggedRtpPacketIncoming, double>(
782 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700783 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700784
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200785 TimeSeries send_time_data(
786 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
787 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100788 AccumulatePairs<LoggedRtpPacketIncoming, double>(
789 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
790 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700791 }
792
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200793 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
794 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700795 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
796 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700797 plot->SetTitle("Network latency (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700798}
799
tereliusf736d232016-08-04 10:00:11 -0700800// Plot the fraction of packets lost (as perceived by the loss-based BWE).
801void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100802 TimeSeries time_series("Fraction lost", LineStyle::kLine,
803 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200804 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200805 float x = ToCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200806 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700807 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700808 }
tereliusf736d232016-08-04 10:00:11 -0700809
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200810 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200811 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
812 kLeftMargin, kRightMargin);
tereliusf736d232016-08-04 10:00:11 -0700813 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
814 kTopMargin);
815 plot->SetTitle("Reported packet loss");
816}
817
terelius54ce6802016-07-13 06:44:41 -0700818// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200819void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
820 // TODO(terelius): This could be provided by the parser.
821 std::multimap<int64_t, size_t> packets_in_order;
822 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
823 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
824 packets_in_order.insert(
825 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700826 }
827
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200828 auto window_begin = packets_in_order.begin();
829 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700830 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700831
832 // Calculate a moving average of the bitrate and store in a TimeSeries.
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100833 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200834 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
835 while (window_end != packets_in_order.end() && window_end->first < time) {
836 bytes_in_window += window_end->second;
837 ++window_end;
terelius54ce6802016-07-13 06:44:41 -0700838 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200839 while (window_begin != packets_in_order.end() &&
840 window_begin->first < time - window_duration_) {
841 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
842 bytes_in_window -= window_begin->second;
843 ++window_begin;
844 }
845 float window_duration_in_seconds =
846 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200847 float x = ToCallTimeSec(time);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200848 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
849 bitrate_series.points.emplace_back(x, y);
850 }
851 plot->AppendTimeSeries(std::move(bitrate_series));
852
853 // Overlay the outgoing REMB over incoming bitrate.
854 TimeSeries remb_series("Remb", LineStyle::kStep);
855 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200856 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200857 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
858 remb_series.points.emplace_back(x, y);
859 }
860 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
861
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200862 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
863 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200864 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
865 plot->SetTitle("Incoming RTP bitrate");
866}
867
868// Plot the total bandwidth used by all RTP streams.
869void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
870 bool show_detector_state,
871 bool show_alr_state) {
872 // TODO(terelius): This could be provided by the parser.
873 std::multimap<int64_t, size_t> packets_in_order;
874 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
875 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
876 packets_in_order.insert(
877 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
878 }
879
880 auto window_begin = packets_in_order.begin();
881 auto window_end = packets_in_order.begin();
882 size_t bytes_in_window = 0;
883
884 // Calculate a moving average of the bitrate and store in a TimeSeries.
885 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
886 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
887 while (window_end != packets_in_order.end() && window_end->first < time) {
888 bytes_in_window += window_end->second;
889 ++window_end;
890 }
891 while (window_begin != packets_in_order.end() &&
892 window_begin->first < time - window_duration_) {
893 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
894 bytes_in_window -= window_begin->second;
895 ++window_begin;
terelius54ce6802016-07-13 06:44:41 -0700896 }
897 float window_duration_in_seconds =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800898 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200899 float x = ToCallTimeSec(time);
terelius54ce6802016-07-13 06:44:41 -0700900 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
philipel35ba9bd2017-04-19 05:58:51 -0700901 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700902 }
philipel35ba9bd2017-04-19 05:58:51 -0700903 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700904
terelius8058e582016-07-25 01:32:41 -0700905 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200906 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
907 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200908 float x = ToCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200909 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
910 loss_series.points.emplace_back(x, y);
911 }
philipel10fc0e62017-04-11 01:50:23 -0700912
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200913 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
914 IntervalSeries overusing_series("Overusing", "#ff8e82",
915 IntervalSeries::kHorizontal);
916 IntervalSeries underusing_series("Underusing", "#5092fc",
917 IntervalSeries::kHorizontal);
918 IntervalSeries normal_series("Normal", "#c4ffc4",
919 IntervalSeries::kHorizontal);
920 IntervalSeries* last_series = &normal_series;
921 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700922
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200923 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700924
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200925 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200926 float x = ToCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200927 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700928
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200929 if (last_detector_state != delay_update.detector_state) {
930 last_series->intervals.emplace_back(last_detector_switch, x);
931 last_detector_state = delay_update.detector_state;
932 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700933
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200934 switch (delay_update.detector_state) {
935 case BandwidthUsage::kBwNormal:
936 last_series = &normal_series;
937 break;
938 case BandwidthUsage::kBwUnderusing:
939 last_series = &underusing_series;
940 break;
941 case BandwidthUsage::kBwOverusing:
942 last_series = &overusing_series;
943 break;
944 case BandwidthUsage::kLast:
945 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200946 }
947 }
philipel23c7f252017-07-14 06:30:03 -0700948
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200949 delay_series.points.emplace_back(x, y);
950 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200951
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200952 RTC_CHECK(last_series);
953 last_series->intervals.emplace_back(last_detector_switch, end_time_);
954
955 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
956 PointStyle::kHighlight);
957 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200958 float x = ToCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200959 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
960 created_series.points.emplace_back(x, y);
961 }
962
963 TimeSeries result_series("Probing results.", LineStyle::kNone,
964 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200965 for (auto& result : parsed_log_.bwe_probe_success_events()) {
966 float x = ToCallTimeSec(result.log_time_us());
967 float y = static_cast<float>(result.bitrate_bps) / 1000;
968 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200969 }
970
971 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
972 bool previously_in_alr = false;
973 int64_t alr_start = 0;
974 for (auto& alr : parsed_log_.alr_state_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200975 float y = ToCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200976 if (!previously_in_alr && alr.in_alr) {
977 alr_start = alr.log_time_us();
978 previously_in_alr = true;
979 } else if (previously_in_alr && !alr.in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200980 float x = ToCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100981 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200982 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +0000983 }
Björn Tereliusff612732018-04-25 14:23:01 +0000984 }
985
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200986 if (previously_in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200987 float x = ToCallTimeSec(alr_start);
988 float y = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200989 alr_state.intervals.emplace_back(x, y);
990 }
991
992 if (show_detector_state) {
993 plot->AppendIntervalSeries(std::move(overusing_series));
994 plot->AppendIntervalSeries(std::move(underusing_series));
995 plot->AppendIntervalSeries(std::move(normal_series));
996 }
997
998 if (show_alr_state) {
999 plot->AppendIntervalSeries(std::move(alr_state));
1000 }
1001 plot->AppendTimeSeries(std::move(loss_series));
1002 plot->AppendTimeSeries(std::move(delay_series));
1003 plot->AppendTimeSeries(std::move(created_series));
1004 plot->AppendTimeSeries(std::move(result_series));
1005
1006 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001007 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001008 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001009 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001010 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001011 remb_series.points.emplace_back(x, y);
1012 }
1013 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1014
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001015 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1016 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001017 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001018 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001019}
1020
1021// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001022void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1023 Plot* plot) {
1024 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1025 // Filter on SSRC.
1026 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001027 continue;
terelius54ce6802016-07-13 06:44:41 -07001028 }
1029
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001030 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1031 LineStyle::kLine);
1032 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1033 return packet.total_length * 8.0 / 1000.0;
1034 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001035 auto ToCallTime = [this](int64_t time) {
1036 return this->ToCallTimeSec(time);
1037 };
terelius53dc23c2017-03-13 05:24:05 -07001038 MovingAverage<LoggedRtpPacket, double>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001039 ToCallTime, GetPacketSizeKilobits, stream.packet_view, begin_time_,
1040 end_time_, window_duration_, step_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001041 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001042 }
1043
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001044 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1045 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001046 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001047 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001048}
1049
Bjorn Terelius28db2662017-10-04 14:22:43 +02001050void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001051 using RtpPacketType = LoggedRtpPacketOutgoing;
1052 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001053
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001054 // TODO(terelius): This could be provided by the parser.
1055 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1056 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1057 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1058 outgoing_rtp.insert(
1059 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001060 }
1061
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001062 const std::vector<TransportFeedbackType>& incoming_rtcp =
1063 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001064
1065 SimulatedClock clock(0);
1066 BitrateObserver observer;
1067 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001068 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001069 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Janssona39a0072018-10-15 20:59:07 +02001070 TransportFeedbackAdapter transport_feedback(&clock);
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001071 auto factory = GoogCcNetworkControllerFactory(&null_event_log);
1072 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001073 // TODO(holmer): Log the call config and use that here instead.
1074 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001075 NetworkControllerConfig cc_config;
Sebastian Jansson78416b62018-10-18 13:08:17 +02001076 cc_config.constraints.at_time = Timestamp::us(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001077 cc_config.constraints.starting_rate = DataRate::bps(kDefaultStartBitrateBps);
1078 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001079
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001080 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1081 PointStyle::kHighlight);
1082 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1083 PointStyle::kHighlight);
1084 TimeSeries acked_estimate_time_series(
1085 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001086
1087 auto rtp_iterator = outgoing_rtp.begin();
1088 auto rtcp_iterator = incoming_rtcp.begin();
1089
1090 auto NextRtpTime = [&]() {
1091 if (rtp_iterator != outgoing_rtp.end())
1092 return static_cast<int64_t>(rtp_iterator->first);
1093 return std::numeric_limits<int64_t>::max();
1094 };
1095
1096 auto NextRtcpTime = [&]() {
1097 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001098 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001099 return std::numeric_limits<int64_t>::max();
1100 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001101 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001102
1103 auto NextProcessTime = [&]() {
1104 if (rtcp_iterator != incoming_rtcp.end() ||
1105 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001106 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001107 }
1108 return std::numeric_limits<int64_t>::max();
1109 };
1110
Stefan Holmer492ee282016-10-27 17:19:20 +02001111 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001112#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1113 // The event_log_visualizer should normally not be compiled with
1114 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1115 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1116 // and piping the output to plot_dynamics.py can be used as a hack to get the
1117 // internal state of various BWE components. In this case, it is important
1118 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1119 // SendSideCongestionController since that would lead to duplicate outputs.
1120 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Karl Wiberg918f50c2018-07-05 11:40:33 +02001121 absl::make_unique<BitrateEstimator>());
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001122#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001123 int64_t time_us =
1124 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001125 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001126 while (time_us != std::numeric_limits<int64_t>::max()) {
1127 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001128 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1129 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1130 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1131 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1132 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
1133 transport_feedback.AddPacket(
1134 rtp_packet.rtp.header.ssrc,
1135 rtp_packet.rtp.header.extension.transportSequenceNumber,
1136 rtp_packet.rtp.total_length, PacedPacketInfo());
1137 rtc::SentPacket sent_packet(
1138 rtp_packet.rtp.header.extension.transportSequenceNumber,
1139 rtp_packet.rtp.log_time_us() / 1000);
1140 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1141 if (sent_msg)
1142 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1143 }
1144 ++rtp_iterator;
1145 }
Stefan Holmer13181032016-07-29 14:48:54 +02001146 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001147 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001148
1149 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
1150 rtcp_iterator->transport_feedback);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001151 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001152 if (feedback_msg) {
1153 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
1154 std::vector<PacketFeedback> feedback =
1155 transport_feedback.GetTransportFeedbackVector();
1156 SortPacketFeedbackVector(&feedback);
1157 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001158#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001159 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001160#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001161 for (const PacketFeedback& packet : feedback)
1162 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1163 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
1164 }
Stefan Holmer13181032016-07-29 14:48:54 +02001165 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001166
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001167 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001168 float y = bitrate_bps.value_or(0) / 1000;
1169 acked_time_series.points.emplace_back(x, y);
1170#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1171 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1172 acked_estimate_time_series.points.emplace_back(x, y);
1173#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001174 ++rtcp_iterator;
1175 }
stefanc3de0332016-08-02 07:22:17 -07001176 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1177 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001178 ProcessInterval msg;
1179 msg.at_time = Timestamp::us(clock.TimeInMicroseconds());
1180 observer.Update(goog_cc->OnProcessInterval(msg));
1181 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001182 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001183 if (observer.GetAndResetBitrateUpdated() ||
1184 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001185 uint32_t y = observer.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001186 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001187 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001188 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001189 }
1190 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1191 }
1192 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001193 plot->AppendTimeSeries(std::move(time_series));
1194 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001195 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001196
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001197 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1198 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001199 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001200 plot->SetTitle("Simulated send-side BWE behavior");
1201}
1202
1203void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001204 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001205 class RembInterceptingPacketRouter : public PacketRouter {
1206 public:
1207 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1208 uint32_t bitrate_bps) override {
1209 last_bitrate_bps_ = bitrate_bps;
1210 bitrate_updated_ = true;
1211 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1212 }
1213 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1214 bool GetAndResetBitrateUpdated() {
1215 bool bitrate_updated = bitrate_updated_;
1216 bitrate_updated_ = false;
1217 return bitrate_updated;
1218 }
1219
1220 private:
1221 uint32_t last_bitrate_bps_;
1222 bool bitrate_updated_;
1223 };
1224
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001225 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001226
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001227 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1228 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1229 for (const auto& rtp_packet : stream.incoming_packets)
1230 incoming_rtp.insert(
1231 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001232 }
1233 }
1234
1235 SimulatedClock clock(0);
1236 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001237 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001238 // Is this intentional?
1239 ReceiveSideCongestionController rscc(&clock, &packet_router);
1240 // TODO(holmer): Log the call config and use that here instead.
1241 // static const uint32_t kDefaultStartBitrateBps = 300000;
1242 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1243
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001244 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1245 PointStyle::kHighlight);
1246 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001247
1248 RateStatistics acked_bitrate(250, 8000);
1249 int64_t last_update_us = 0;
1250 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001251 const RtpPacketType& packet = *kv.second;
1252 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1253 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1254 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001255 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001256 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001257 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001258 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001259 if (bitrate_bps) {
1260 uint32_t y = *bitrate_bps / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001261 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001262 acked_time_series.points.emplace_back(x, y);
1263 }
1264 if (packet_router.GetAndResetBitrateUpdated() ||
1265 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1266 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001267 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001268 time_series.points.emplace_back(x, y);
1269 last_update_us = clock.TimeInMicroseconds();
1270 }
1271 }
1272 // Add the data set to the plot.
1273 plot->AppendTimeSeries(std::move(time_series));
1274 plot->AppendTimeSeries(std::move(acked_time_series));
1275
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001276 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1277 kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001278 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1279 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001280}
1281
tereliuse34c19c2016-08-15 08:47:14 -07001282void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001283 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1284 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001285 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001286 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001287 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1288 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001289
stefana0a8ed72017-09-06 02:06:32 -07001290 int64_t prev_y = 0;
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001291 for (auto packet : GetNetworkTrace(parsed_log_)) {
1292 if (packet.arrival_time_ms == PacketFeedback::kNotReceived)
1293 continue;
1294 float x = ToCallTimeSec(1000 * packet.feedback_arrival_time_ms);
1295 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1296 late_feedback_series.points.emplace_back(x, prev_y);
1297 continue;
stefanc3de0332016-08-02 07:22:17 -07001298 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001299 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1300 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001301 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1302 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1303 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001304 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001305 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001306
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001307 // We assume that the base network delay (w/o queues) is equal to half
1308 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1309 // observed 1-ways delay and add half the minumum RTT.
1310 const int64_t estimated_clock_offset_ms =
1311 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001312 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001313 point.y -= estimated_clock_offset_ms;
stefana0a8ed72017-09-06 02:06:32 -07001314 for (TimeSeriesPoint& point : late_feedback_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001315 point.y -= estimated_clock_offset_ms;
1316
stefanc3de0332016-08-02 07:22:17 -07001317 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001318 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1319 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001320
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001321 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1322 kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001323 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001324 plot->SetTitle("Network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001325}
stefan08383272016-12-20 08:51:52 -08001326
Bjorn Terelius0295a962017-10-25 17:42:41 +02001327void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001328 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1329 const std::vector<LoggedRtpPacketOutgoing>& packets =
1330 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001331
1332 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001333 RTC_LOG(LS_WARNING)
1334 << "Can't estimate a the RTP clock frequency or the "
1335 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001336 continue;
1337 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001338 int64_t end_time_us = log_segments_.empty()
1339 ? std::numeric_limits<int64_t>::max()
1340 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001341 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001342 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001343 if (!estimated_frequency)
1344 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001345 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1346 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001347 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001348 << "Video stream should use a 90 kHz clock but appears to use "
1349 << *estimated_frequency / 1000 << ". Discarding.";
1350 continue;
1351 }
1352
1353 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001354 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001355 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001356 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001357 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1358 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001359 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1360 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1361 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001362 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001363 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001364 first_capture_timestamp) /
1365 *estimated_frequency * 1000;
1366 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001367 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1368 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001369 float x = ToCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001370 float y = send_time_ms - capture_time_ms;
1371 pacer_delay_series.points.emplace_back(x, y);
1372 }
1373 plot->AppendTimeSeries(std::move(pacer_delay_series));
1374 }
1375
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001376 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1377 kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001378 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1379 plot->SetTitle(
1380 "Delay from capture to send time. (First packet normalized to 0.)");
1381}
1382
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001383void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1384 Plot* plot) {
1385 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1386 TimeSeries rtp_timestamps(
1387 GetStreamName(direction, stream.ssrc) + " capture-time",
1388 LineStyle::kLine, PointStyle::kHighlight);
1389 for (const auto& packet : stream.packet_view) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001390 float x = ToCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001391 float y = packet.header.timestamp;
1392 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001393 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001394 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001395
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001396 TimeSeries rtcp_timestamps(
1397 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1398 LineStyle::kLine, PointStyle::kHighlight);
1399 // TODO(terelius): Why only sender reports?
1400 const auto& sender_reports = parsed_log_.sender_reports(direction);
1401 for (const auto& rtcp : sender_reports) {
1402 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1403 continue;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001404 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001405 float y = rtcp.sr.rtp_timestamp();
1406 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001407 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001408 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001409 }
1410
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001411 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1412 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001413 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1414 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001415}
michaelt6e5b2192017-02-22 07:33:27 -08001416
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001417void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1418 PacketDirection direction,
1419 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1420 std::string title,
1421 std::string yaxis_label,
1422 Plot* plot) {
1423 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1424 const auto& sender_reports = parsed_log_.sender_reports(direction);
1425 for (const auto& rtcp : sender_reports) {
1426 float x = ToCallTimeSec(rtcp.log_time_us());
1427 uint32_t ssrc = rtcp.sr.sender_ssrc();
1428 for (const auto& block : rtcp.sr.report_blocks()) {
1429 float y = fy(block);
1430 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1431 bool inserted;
1432 if (sr_report_it == sr_reports_by_ssrc.end()) {
1433 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1434 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1435 LineStyle::kLine, PointStyle::kHighlight));
1436 }
1437 sr_report_it->second.points.emplace_back(x, y);
1438 }
1439 }
1440 for (auto& kv : sr_reports_by_ssrc) {
1441 plot->AppendTimeSeries(std::move(kv.second));
1442 }
1443
1444 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1445 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1446 for (const auto& rtcp : receiver_reports) {
1447 float x = ToCallTimeSec(rtcp.log_time_us());
1448 uint32_t ssrc = rtcp.rr.sender_ssrc();
1449 for (const auto& block : rtcp.rr.report_blocks()) {
1450 float y = fy(block);
1451 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1452 bool inserted;
1453 if (rr_report_it == rr_reports_by_ssrc.end()) {
1454 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1455 ssrc,
1456 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1457 LineStyle::kLine, PointStyle::kHighlight));
1458 }
1459 rr_report_it->second.points.emplace_back(x, y);
1460 }
1461 }
1462 for (auto& kv : rr_reports_by_ssrc) {
1463 plot->AppendTimeSeries(std::move(kv.second));
1464 }
1465
1466 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1467 kLeftMargin, kRightMargin);
1468 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1469 plot->SetTitle(title);
1470}
1471
michaelt6e5b2192017-02-22 07:33:27 -08001472void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001473 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1474 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001475 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001476 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001477 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001478 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001479 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001480 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001481 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001482 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1483 return this->ToCallTimeSec(packet.log_time_us());
1484 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001485 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001486 ToCallTime, GetAnaBitrateBps,
1487 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001488 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001489 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1490 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001491 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1492 plot->SetTitle("Reported audio encoder target bitrate");
1493}
1494
1495void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001496 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1497 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001498 auto GetAnaFrameLengthMs =
1499 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001500 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001501 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001502 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001503 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001504 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001505 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1506 return this->ToCallTimeSec(packet.log_time_us());
1507 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001508 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001509 ToCallTime, GetAnaFrameLengthMs,
1510 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001511 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001512 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1513 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001514 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1515 plot->SetTitle("Reported audio encoder frame length");
1516}
1517
terelius2ee076d2017-08-15 02:04:02 -07001518void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001519 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001520 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001521 auto GetAnaPacketLoss =
1522 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001523 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001524 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001525 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001526 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001527 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001528 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1529 return this->ToCallTimeSec(packet.log_time_us());
1530 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001531 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001532 ToCallTime, GetAnaPacketLoss,
1533 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001534 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001535 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1536 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001537 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1538 kTopMargin);
1539 plot->SetTitle("Reported audio encoder lost packets");
1540}
1541
1542void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001543 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1544 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001545 auto GetAnaFecEnabled =
1546 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001547 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001548 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001549 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001550 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001551 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001552 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1553 return this->ToCallTimeSec(packet.log_time_us());
1554 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001555 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001556 ToCallTime, GetAnaFecEnabled,
1557 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001558 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001559 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1560 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001561 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1562 plot->SetTitle("Reported audio encoder FEC");
1563}
1564
1565void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001566 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1567 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001568 auto GetAnaDtxEnabled =
1569 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001570 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001571 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001572 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001573 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001574 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001575 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1576 return this->ToCallTimeSec(packet.log_time_us());
1577 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001578 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001579 ToCallTime, GetAnaDtxEnabled,
1580 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001581 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001582 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1583 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001584 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1585 plot->SetTitle("Reported audio encoder DTX");
1586}
1587
1588void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001589 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1590 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001591 auto GetAnaNumChannels =
1592 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001593 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001594 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001595 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001596 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001597 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001598 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1599 return this->ToCallTimeSec(packet.log_time_us());
1600 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001601 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001602 ToCallTime, GetAnaNumChannels,
1603 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001604 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001605 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1606 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001607 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1608 kBottomMargin, kTopMargin);
1609 plot->SetTitle("Reported audio encoder number of channels");
1610}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001611
1612class NetEqStreamInput : public test::NetEqInput {
1613 public:
1614 // Does not take any ownership, and all pointers must refer to valid objects
1615 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001616 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001617 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001618 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001619 : packet_stream_(*packet_stream),
1620 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001621 output_events_it_(output_events->begin()),
1622 output_events_end_(output_events->end()),
1623 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001624 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001625 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001626 }
1627
Danil Chapovalov431abd92018-06-18 12:54:17 +02001628 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001629 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001630 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001631 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001632 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001633 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001634 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001635 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001636 }
1637
Danil Chapovalov431abd92018-06-18 12:54:17 +02001638 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001639 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001640 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001641 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001642 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001643 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001644 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001645 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001646 }
1647
1648 std::unique_ptr<PacketData> PopPacket() override {
1649 if (packet_stream_it_ == packet_stream_.end()) {
1650 return std::unique_ptr<PacketData>();
1651 }
1652 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001653 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001654 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001655
1656 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1657 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001658 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1659 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001660 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1661
1662 ++packet_stream_it_;
1663 return packet_data;
1664 }
1665
1666 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001667 if (output_events_it_ != output_events_end_) {
1668 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001669 }
1670 }
1671
1672 bool ended() const override { return !NextEventTime(); }
1673
Danil Chapovalov431abd92018-06-18 12:54:17 +02001674 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001675 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001676 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001677 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001678 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001679 }
1680
1681 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001682 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1683 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001684 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1685 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001686 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001687};
1688
1689namespace {
1690// Creates a NetEq test object and all necessary input and output helpers. Runs
1691// the test and returns the NetEqDelayAnalyzer object that was used to
1692// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001693std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001694 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001695 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001696 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001697 const std::string& replacement_file_name,
1698 int file_sample_rate_hz) {
1699 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001700 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001701
1702 constexpr int kReplacementPt = 127;
1703 std::set<uint8_t> cn_types;
1704 std::set<uint8_t> forbidden_types;
1705 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1706 cn_types, forbidden_types));
1707
1708 NetEq::Config config;
1709 config.max_packets_in_buffer = 200;
1710 config.enable_fast_accelerate = true;
1711
1712 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1713
Niels Möllerdaa970f2018-12-17 09:33:55 +01001714 // Factory to create a "replacement decoder" that produces the decoded audio
1715 // by reading from a file rather than from the encoded payloads.
1716 rtc::scoped_refptr<AudioDecoderFactory> decoder_factory =
1717 new rtc::RefCountedObject<test::FunctionAudioDecoderFactory>(
1718 [replacement_file_name, file_sample_rate_hz]() {
1719 std::unique_ptr<test::ResampleInputAudioFile> replacement_file(
1720 new test::ResampleInputAudioFile(replacement_file_name,
1721 file_sample_rate_hz));
1722 replacement_file->set_output_rate_hz(48000);
1723 return absl::make_unique<test::FakeDecodeFromFile>(
1724 std::move(replacement_file), 48000, false);
1725 });
1726
henrik.lundin3c938fc2017-06-14 06:09:58 -07001727 test::NetEqTest::DecoderMap codecs;
1728
Niels Möllerdaa970f2018-12-17 09:33:55 +01001729 codecs[kReplacementPt] = {NetEqDecoder::kDecoderPCM16Bswb48kHz,
1730 "replacement codec"};
henrik.lundin3c938fc2017-06-14 06:09:58 -07001731
1732 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1733 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001734 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1735 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001736 test::DefaultNetEqTestErrorCallback error_cb;
1737 test::NetEqTest::Callbacks callbacks;
1738 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001739 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1740 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001741
Niels Möllerdaa970f2018-12-17 09:33:55 +01001742 test::NetEqTest::ExtDecoderMap ext_codecs;
1743 test::NetEqTest test(config, decoder_factory, codecs, ext_codecs, nullptr,
1744 std::move(input), std::move(output), callbacks);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001745 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001746 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001747}
1748} // namespace
1749
Minyue Lic6ff7572018-05-04 09:46:44 +02001750EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001751 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001752 int file_sample_rate_hz) const {
1753 NetEqStatsGetterMap neteq_stats;
1754
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001755 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001756 const uint32_t ssrc = stream.ssrc;
1757 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1758 continue;
1759 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1760 &stream.incoming_packets;
1761 if (audio_packets == nullptr) {
1762 // No incoming audio stream found.
1763 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001764 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001765
Minyue Li27e2b7d2018-05-07 15:20:24 +02001766 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1767
1768 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1769 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1770 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1771 // Could not find output events with SSRC matching the input audio stream.
1772 // Using the first available stream of output events.
1773 output_events_it = parsed_log_.audio_playout_events().cbegin();
1774 }
1775
Danil Chapovalov431abd92018-06-18 12:54:17 +02001776 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001777 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001778 ? absl::nullopt
1779 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001780
1781 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1782 audio_packets, &output_events_it->second, end_time_ms,
1783 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001784 }
1785
Minyue Lic6ff7572018-05-04 09:46:44 +02001786 return neteq_stats;
1787}
1788
Minyue Lic97933f2018-08-10 12:51:15 +02001789// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1790// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001791void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001792 uint32_t ssrc,
1793 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001794 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001795 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1796 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1797 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1798 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1799
Minyue Li01d2a672018-06-21 21:17:19 +02001800 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001801 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1802 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001803
Minyue Lic97933f2018-08-10 12:51:15 +02001804 TimeSeries time_series_packet_arrival("packet arrival delay",
1805 LineStyle::kLine);
1806 TimeSeries time_series_relative_packet_arrival(
1807 "Relative packet arrival delay", LineStyle::kLine);
1808 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
1809 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
1810 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02001811
1812 for (const auto& data : arrival_delay_ms) {
1813 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1814 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001815 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001816 }
1817 for (const auto& data : corrected_arrival_delay_ms) {
1818 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1819 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001820 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02001821 TimeSeriesPoint(x, y));
1822 }
1823 for (const auto& data : playout_delay_ms) {
1824 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1825 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001826 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001827 }
1828 for (const auto& data : target_delay_ms) {
1829 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1830 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001831 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001832 }
1833
Minyue Lic97933f2018-08-10 12:51:15 +02001834 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
1835 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
1836 plot->AppendTimeSeries(std::move(time_series_play_time));
1837 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001838
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001839 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1840 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001841 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
1842 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001843 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
1844}
1845
Minyue Lic9ac93f2018-06-26 13:01:32 +02001846template <typename NetEqStatsType>
1847void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001848 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02001849 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
1850 const test::NetEqStatsGetter*)> data_extractor,
1851 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001852 const std::string& plot_name,
1853 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001854 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001855
1856 for (const auto& st : neteq_stats) {
1857 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02001858 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
1859 data_extractor(st.second.get());
1860 for (const auto& data : *data_vector) {
1861 const float time = ToCallTimeSec(data.first * 1000); // ms to us.
1862 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001863 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02001864 }
1865 }
1866
1867 for (auto& series : time_series) {
1868 series.second.label = GetStreamName(kIncomingPacket, series.first);
1869 series.second.line_style = LineStyle::kLine;
1870 plot->AppendTimeSeries(std::move(series.second));
1871 }
1872
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001873 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1874 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001875 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001876 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001877}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001878
Minyue Lic9ac93f2018-06-26 13:01:32 +02001879void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
1880 const NetEqStatsGetterMap& neteq_stats,
1881 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
1882 const std::string& plot_name,
1883 Plot* plot) const {
1884 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
1885 neteq_stats,
1886 [](const test::NetEqStatsGetter* stats_getter) {
1887 return stats_getter->stats();
1888 },
1889 stats_extractor, plot_name, plot);
1890}
1891
1892void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
1893 const NetEqStatsGetterMap& neteq_stats,
1894 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
1895 const std::string& plot_name,
1896 Plot* plot) const {
1897 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
1898 neteq_stats,
1899 [](const test::NetEqStatsGetter* stats_getter) {
1900 return stats_getter->lifetime_stats();
1901 },
1902 stats_extractor, plot_name, plot);
1903}
1904
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001905void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1906 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001907 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001908 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1909 configs_by_cp_id.end()) {
1910 const std::string candidate_pair_desc =
1911 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001912 configs_by_cp_id[config.candidate_pair_id] =
1913 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1914 candidate_pair_desc,
1915 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001916 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1917 candidate_pair_desc;
1918 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001919 float x = ToCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001920 float y = static_cast<float>(config.type);
1921 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1922 }
1923
1924 // TODO(qingsi): There can be a large number of candidate pairs generated by
1925 // certain calls and the frontend cannot render the chart in this case due to
1926 // the failure of generating a palette with the same number of colors.
1927 for (auto& kv : configs_by_cp_id) {
1928 plot->AppendTimeSeries(std::move(kv.second));
1929 }
1930
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001931 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1932 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001933 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
1934 kTopMargin);
1935 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1936}
1937
1938std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1939 uint32_t candidate_pair_id) {
1940 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1941 candidate_pair_desc_by_id_.end()) {
1942 return candidate_pair_desc_by_id_[candidate_pair_id];
1943 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001944 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001945 // TODO(qingsi): Add the handling of the "Updated" config event after the
1946 // visualization of property change for candidate pairs is introduced.
1947 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1948 candidate_pair_desc_by_id_.end()) {
1949 const std::string candidate_pair_desc =
1950 GetCandidatePairLogDescriptionAsString(config);
1951 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1952 candidate_pair_desc;
1953 }
1954 }
1955 return candidate_pair_desc_by_id_[candidate_pair_id];
1956}
1957
1958void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1959 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001960 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001961 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1962 checks_by_cp_id.end()) {
1963 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08001964 "[" + std::to_string(event.candidate_pair_id) + "]" +
1965 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001966 LineStyle::kNone, PointStyle::kHighlight);
1967 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001968 float x = ToCallTimeSec(event.log_time_us());
Zach Stein6353fbc2018-12-03 14:35:59 -08001969 constexpr int kIceCandidatePairEventTypeOffset =
1970 static_cast<int>(IceCandidatePairConfigType::kNumValues);
1971 float y = static_cast<float>(event.type) + kIceCandidatePairEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001972 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1973 }
1974
1975 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1976 for (auto& kv : checks_by_cp_id) {
1977 plot->AppendTimeSeries(std::move(kv.second));
1978 }
1979
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001980 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1981 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001982 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
1983 kTopMargin);
1984 plot->SetTitle("[IceEventLog] ICE connectivity checks");
1985}
1986
Zach Stein10a58012018-12-07 12:26:28 -08001987void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
1988 TimeSeries states("DTLS Transport State", LineStyle::kNone,
1989 PointStyle::kHighlight);
1990 for (const auto& event : parsed_log_.dtls_transport_states()) {
1991 float x = ToCallTimeSec(event.log_time_us());
1992 float y = static_cast<float>(event.dtls_transport_state);
1993 states.points.emplace_back(x, y);
1994 }
1995 plot->AppendTimeSeries(std::move(states));
1996 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1997 kLeftMargin, kRightMargin);
1998 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
1999 "Numeric Transport State", kBottomMargin, kTopMargin);
2000 plot->SetTitle("DTLS Transport State");
2001}
2002
2003void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
2004 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2005 PointStyle::kHighlight);
2006 for (const auto& event : parsed_log_.dtls_writable_states()) {
2007 float x = ToCallTimeSec(event.log_time_us());
2008 float y = static_cast<float>(event.writable);
2009 writable.points.emplace_back(x, y);
2010 }
2011 plot->AppendTimeSeries(std::move(writable));
2012 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
2013 kLeftMargin, kRightMargin);
2014 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2015 plot->SetTitle("DTLS Writable State");
2016}
2017
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002018void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002019 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002020 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2021 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2022 }
2023 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2024 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2025 }
2026 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2027 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2028 }
2029 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2030 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2031 }
2032 for (const auto& alert : incoming_seq_num_jumps_) {
2033 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2034 }
2035 for (const auto& alert : incoming_capture_time_jumps_) {
2036 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2037 }
2038 for (const auto& alert : outgoing_seq_num_jumps_) {
2039 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2040 }
2041 for (const auto& alert : outgoing_capture_time_jumps_) {
2042 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2043 }
2044 for (const auto& alert : outgoing_high_loss_alerts_) {
2045 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002046 }
2047 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2048}
2049
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002050void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2051 // With 100 packets/s (~800kbps), false positives would require 10 s without
2052 // data.
2053 constexpr int64_t kMaxSeqNumJump = 1000;
2054 // With a 90 kHz clock, false positives would require 10 s without data.
2055 constexpr int64_t kMaxCaptureTimeJump = 900000;
2056
2057 int64_t end_time_us = log_segments_.empty()
2058 ? std::numeric_limits<int64_t>::max()
2059 : log_segments_.front().second;
2060
2061 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002062 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002063 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002064 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002065 // Check for gaps in sequence numbers and capture timestamps.
2066 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2067 for (const auto& packet : stream.packet_view) {
2068 if (packet.log_time_us() > end_time_us) {
2069 // Only process the first (LOG_START, LOG_END) segment.
2070 break;
2071 }
2072
2073 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2074 if (last_seq_num.has_value() &&
2075 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002076 Alert_SeqNumJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002077 packet.header.ssrc);
2078 }
2079 last_seq_num.emplace(seq_num);
2080
2081 int64_t capture_time =
2082 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2083 if (last_capture_time.has_value() &&
2084 std::abs(capture_time - last_capture_time.value()) >
2085 kMaxCaptureTimeJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002086 Alert_CaptureTimeJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002087 packet.header.ssrc);
2088 }
2089 last_capture_time.emplace(capture_time);
2090 }
2091 }
2092}
2093
2094void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2095 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2096 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2097 int64_t end_time_us = log_segments_.empty()
2098 ? std::numeric_limits<int64_t>::max()
2099 : log_segments_.front().second;
2100
2101 // TODO(terelius): The parser could provide a list of all packets, ordered
2102 // by time, for each direction.
2103 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2104 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2105 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2106 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2107 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002108 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002109 for (const auto& kv : rtp_in_direction) {
2110 int64_t timestamp = kv.first;
2111 if (timestamp > end_time_us) {
2112 // Only process the first (LOG_START, LOG_END) segment.
2113 break;
2114 }
2115 int64_t duration = timestamp - last_rtp_time.value_or(0);
2116 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2117 // No packet sent/received for more than 500 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002118 Alert_RtpLogTimeGap(direction, ToCallTimeSec(timestamp), duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002119 }
2120 last_rtp_time.emplace(timestamp);
2121 }
2122
Danil Chapovalov431abd92018-06-18 12:54:17 +02002123 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002124 if (direction == kIncomingPacket) {
2125 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2126 if (rtcp.log_time_us() > end_time_us) {
2127 // Only process the first (LOG_START, LOG_END) segment.
2128 break;
2129 }
2130 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2131 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2132 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002133 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002134 duration / 1000);
2135 }
2136 last_rtcp_time.emplace(rtcp.log_time_us());
2137 }
2138 } else {
2139 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2140 if (rtcp.log_time_us() > end_time_us) {
2141 // Only process the first (LOG_START, LOG_END) segment.
2142 break;
2143 }
2144 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2145 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2146 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002147 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002148 duration / 1000);
2149 }
2150 last_rtcp_time.emplace(rtcp.log_time_us());
2151 }
2152 }
2153}
2154
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002155// TODO(terelius): Notifications could possibly be generated by the same code
2156// that produces the graphs. There is some code duplication that could be
2157// avoided, but that might be solved anyway when we move functionality from the
2158// analyzer to the parser.
2159void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002160 CreateStreamGapAlerts(kIncomingPacket);
2161 CreateStreamGapAlerts(kOutgoingPacket);
2162 CreateTransmissionGapAlerts(kIncomingPacket);
2163 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002164
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002165 int64_t end_time_us = log_segments_.empty()
2166 ? std::numeric_limits<int64_t>::max()
2167 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002168
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002169 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002170 // Loss feedback
2171 int64_t total_lost_packets = 0;
2172 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002173 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2174 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002175 // Only process the first (LOG_START, LOG_END) segment.
2176 break;
2177 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002178 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002179 bwe_update.expected_packets;
2180 total_lost_packets += lost_packets;
2181 total_expected_packets += bwe_update.expected_packets;
2182 }
2183 double avg_outgoing_loss =
2184 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002185 if (avg_outgoing_loss > kMaxLossFraction) {
2186 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002187 }
2188}
2189
terelius54ce6802016-07-13 06:44:41 -07002190} // namespace webrtc