blob: 7cf003991bb0bf14b2ba8100ebf400d9727b9cca [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"
terelius54ce6802016-07-13 06:44:41 -070060
Bjorn Terelius6984ad22017-10-24 12:19:45 +020061#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
62#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
63#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
64
tereliusdc35dcd2016-08-01 12:03:27 -070065namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070066
terelius54ce6802016-07-13 06:44:41 -070067namespace {
68
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080069const int kNumMicrosecsPerSec = 1000000;
70
elad.alonec304f92017-03-08 05:03:53 -080071void SortPacketFeedbackVector(std::vector<PacketFeedback>* vec) {
72 auto pred = [](const PacketFeedback& packet_feedback) {
73 return packet_feedback.arrival_time_ms == PacketFeedback::kNotReceived;
74 };
75 vec->erase(std::remove_if(vec->begin(), vec->end(), pred), vec->end());
76 std::sort(vec->begin(), vec->end(), PacketFeedbackComparator());
77}
78
terelius54ce6802016-07-13 06:44:41 -070079std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020080 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070081 ss << "SSRC " << ssrc;
Jonas Olsson84df1c72018-09-14 16:59:32 +020082 return ss.Release();
terelius54ce6802016-07-13 06:44:41 -070083}
84
85// Checks whether an SSRC is contained in the list of desired SSRCs.
86// Note that an empty SSRC list matches every SSRC.
87bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
88 if (desired_ssrc.size() == 0)
89 return true;
90 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
91 desired_ssrc.end();
92}
93
94double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
95 // The timestamp is a fixed point representation with 6 bits for seconds
96 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080097 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
98 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070099 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800100 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -0700101 return abs_send_time * kTimestampToMicroSec;
102}
103
104// Computes the difference |later| - |earlier| where |later| and |earlier|
105// are counters that wrap at |modulus|. The difference is chosen to have the
106// least absolute value. For example if |modulus| is 8, then the difference will
107// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
108// be in [-4, 4].
109int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
110 RTC_DCHECK_LE(1, modulus);
111 RTC_DCHECK_LT(later, modulus);
112 RTC_DCHECK_LT(earlier, modulus);
113 int64_t difference =
114 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
115 int64_t max_difference = modulus / 2;
116 int64_t min_difference = max_difference - modulus + 1;
117 if (difference > max_difference) {
118 difference -= modulus;
119 }
120 if (difference < min_difference) {
121 difference += modulus;
122 }
terelius6addf492016-08-23 17:34:07 -0700123 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100124 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
125 << " expected to be in the range ("
126 << min_difference / 2 << "," << max_difference / 2
127 << ") but is " << difference
128 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700129 }
terelius54ce6802016-07-13 06:44:41 -0700130 return difference;
131}
132
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200133// This is much more reliable for outgoing streams than for incoming streams.
134template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200135absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200136 const RtpPacketContainer& packets,
137 int64_t end_time_us) {
138 RTC_CHECK(packets.size() >= 2);
139 SeqNumUnwrapper<uint32_t> unwrapper;
140 uint64_t first_rtp_timestamp =
141 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
142 int64_t first_log_timestamp = packets[0].log_time_us();
143 uint64_t last_rtp_timestamp = first_rtp_timestamp;
144 int64_t last_log_timestamp = first_log_timestamp;
145 for (size_t i = 1; i < packets.size(); i++) {
146 if (packets[i].log_time_us() > end_time_us)
147 break;
148 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
149 last_log_timestamp = packets[i].log_time_us();
150 }
151 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
152 RTC_LOG(LS_WARNING)
153 << "Failed to estimate RTP clock frequency: Stream too short. ("
154 << packets.size() << " packets, "
155 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200156 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200157 }
158 double duration =
159 static_cast<double>(last_log_timestamp - first_log_timestamp) /
160 kNumMicrosecsPerSec;
161 double estimated_frequency =
162 (last_rtp_timestamp - first_rtp_timestamp) / duration;
163 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
164 if (std::fabs(estimated_frequency - f) < 0.05 * f) {
165 return f;
166 }
167 }
168 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
169 << estimated_frequency
170 << "not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200171 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700172}
173
tereliusdc35dcd2016-08-01 12:03:27 -0700174constexpr float kLeftMargin = 0.01f;
175constexpr float kRightMargin = 0.02f;
176constexpr float kBottomMargin = 0.02f;
177constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700178
Danil Chapovalov431abd92018-06-18 12:54:17 +0200179absl::optional<double> NetworkDelayDiff_AbsSendTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100180 const LoggedRtpPacketIncoming& old_packet,
181 const LoggedRtpPacketIncoming& new_packet) {
182 if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
183 new_packet.rtp.header.extension.hasAbsoluteSendTime) {
terelius53dc23c2017-03-13 05:24:05 -0700184 int64_t send_time_diff = WrappingDifference(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100185 new_packet.rtp.header.extension.absoluteSendTime,
186 old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200187 int64_t recv_time_diff =
188 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700189 double delay_change_us =
190 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100191 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700192 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200193 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700194 }
195}
196
Danil Chapovalov431abd92018-06-18 12:54:17 +0200197absl::optional<double> NetworkDelayDiff_CaptureTime(
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100198 const LoggedRtpPacketIncoming& old_packet,
199 const LoggedRtpPacketIncoming& new_packet,
200 const double sample_rate) {
201 int64_t send_time_diff =
202 WrappingDifference(new_packet.rtp.header.timestamp,
203 old_packet.rtp.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200204 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700205
terelius53dc23c2017-03-13 05:24:05 -0700206 double delay_change =
207 static_cast<double>(recv_time_diff) / 1000 -
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100208 static_cast<double>(send_time_diff) / sample_rate * 1000;
terelius53dc23c2017-03-13 05:24:05 -0700209 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100210 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100211 RTC_LOG(LS_WARNING) << "Old capture time "
212 << old_packet.rtp.header.timestamp << ", received time "
213 << old_packet.log_time_us();
214 RTC_LOG(LS_WARNING) << "New capture time "
215 << new_packet.rtp.header.timestamp << ", received time "
216 << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100217 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800218 << static_cast<double>(recv_time_diff) /
219 kNumMicrosecsPerSec
220 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100221 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100222 << static_cast<double>(send_time_diff) / sample_rate
Mirko Bonadei675513b2017-11-09 11:09:25 +0100223 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700224 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100225 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700226}
227
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200228// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700229// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200230template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200231void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200232 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200233 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200234 TimeSeries* result) {
235 for (size_t i = 0; i < data_view.size(); i++) {
236 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200237 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200238 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700239 if (y)
240 result->points.emplace_back(x, *y);
241 }
242}
243
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200244// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700245// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
246// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200247template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700248void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200249 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200250 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
251 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200252 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700253 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700254 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200255 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200256 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700257 if (y)
258 result->points.emplace_back(x, static_cast<float>(*y));
259 }
260}
261
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200262// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700263// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
264// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200265template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700266void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200267 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200268 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
269 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200270 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700271 TimeSeries* result) {
272 ResultType sum = 0;
273 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200274 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200275 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100276 if (y) {
terelius53dc23c2017-03-13 05:24:05 -0700277 sum += *y;
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100278 result->points.emplace_back(x, static_cast<float>(sum));
279 }
tereliusccbbf8d2016-08-10 07:34:28 -0700280 }
281}
282
terelius6addf492016-08-23 17:34:07 -0700283// Calculates a moving average of |data| and stores the result in a TimeSeries.
284// A data point is generated every |step| microseconds from |begin_time|
285// to |end_time|. The value of each data point is the average of the data
286// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200287template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700288void MovingAverage(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200289 rtc::FunctionView<float(int64_t)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200290 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200291 const IterableType& data_view,
292 int64_t begin_time,
293 int64_t end_time,
294 int64_t window_duration_us,
295 int64_t step,
296 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700297 size_t window_index_begin = 0;
298 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700299 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700300
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200301 for (int64_t t = begin_time; t < end_time + step; t += step) {
302 while (window_index_end < data_view.size() &&
303 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200304 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700305 if (value)
306 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700307 ++window_index_end;
308 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200309 while (window_index_begin < data_view.size() &&
310 data_view[window_index_begin].log_time_us() <
311 t - window_duration_us) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200312 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700313 if (value)
314 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700315 ++window_index_begin;
316 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800317 float window_duration_s =
318 static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200319 float x = fx(t);
terelius53dc23c2017-03-13 05:24:05 -0700320 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700321 result->points.emplace_back(x, y);
322 }
323}
324
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800325const char kUnknownEnumValue[] = "unknown";
326
327const char kIceCandidateTypeLocal[] = "local";
328const char kIceCandidateTypeStun[] = "stun";
329const char kIceCandidateTypePrflx[] = "prflx";
330const char kIceCandidateTypeRelay[] = "relay";
331
332const char kProtocolUdp[] = "udp";
333const char kProtocolTcp[] = "tcp";
334const char kProtocolSsltcp[] = "ssltcp";
335const char kProtocolTls[] = "tls";
336
337const char kAddressFamilyIpv4[] = "ipv4";
338const char kAddressFamilyIpv6[] = "ipv6";
339
340const char kNetworkTypeEthernet[] = "ethernet";
341const char kNetworkTypeLoopback[] = "loopback";
342const char kNetworkTypeWifi[] = "wifi";
343const char kNetworkTypeVpn[] = "vpn";
344const char kNetworkTypeCellular[] = "cellular";
345
346std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
347 switch (type) {
348 case webrtc::IceCandidateType::kLocal:
349 return kIceCandidateTypeLocal;
350 case webrtc::IceCandidateType::kStun:
351 return kIceCandidateTypeStun;
352 case webrtc::IceCandidateType::kPrflx:
353 return kIceCandidateTypePrflx;
354 case webrtc::IceCandidateType::kRelay:
355 return kIceCandidateTypeRelay;
356 default:
357 return kUnknownEnumValue;
358 }
359}
360
361std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
362 switch (protocol) {
363 case webrtc::IceCandidatePairProtocol::kUdp:
364 return kProtocolUdp;
365 case webrtc::IceCandidatePairProtocol::kTcp:
366 return kProtocolTcp;
367 case webrtc::IceCandidatePairProtocol::kSsltcp:
368 return kProtocolSsltcp;
369 case webrtc::IceCandidatePairProtocol::kTls:
370 return kProtocolTls;
371 default:
372 return kUnknownEnumValue;
373 }
374}
375
376std::string GetAddressFamilyAsString(
377 webrtc::IceCandidatePairAddressFamily family) {
378 switch (family) {
379 case webrtc::IceCandidatePairAddressFamily::kIpv4:
380 return kAddressFamilyIpv4;
381 case webrtc::IceCandidatePairAddressFamily::kIpv6:
382 return kAddressFamilyIpv6;
383 default:
384 return kUnknownEnumValue;
385 }
386}
387
388std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
389 switch (type) {
390 case webrtc::IceCandidateNetworkType::kEthernet:
391 return kNetworkTypeEthernet;
392 case webrtc::IceCandidateNetworkType::kLoopback:
393 return kNetworkTypeLoopback;
394 case webrtc::IceCandidateNetworkType::kWifi:
395 return kNetworkTypeWifi;
396 case webrtc::IceCandidateNetworkType::kVpn:
397 return kNetworkTypeVpn;
398 case webrtc::IceCandidateNetworkType::kCellular:
399 return kNetworkTypeCellular;
400 default:
401 return kUnknownEnumValue;
402 }
403}
404
405std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200406 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800407 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
408 // represents a pair of a local server-reflexive candidate on a WiFi network
409 // and a remote relay candidate using TCP as the relay protocol on a cell
410 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200411 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800412 std::string local_candidate_type =
413 GetIceCandidateTypeAsString(config.local_candidate_type);
414 std::string remote_candidate_type =
415 GetIceCandidateTypeAsString(config.remote_candidate_type);
416 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
417 local_candidate_type +=
418 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
419 }
420 ss << local_candidate_type << ":"
421 << GetNetworkTypeAsString(config.local_network_type) << ":"
422 << GetAddressFamilyAsString(config.local_address_family) << "->"
423 << remote_candidate_type << ":"
424 << GetAddressFamilyAsString(config.remote_address_family) << "@"
425 << GetProtocolAsString(config.candidate_pair_protocol);
Jonas Olsson84df1c72018-09-14 16:59:32 +0200426 return ss.Release();
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800427}
428
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200429std::string GetDirectionAsString(PacketDirection direction) {
430 if (direction == kIncomingPacket) {
431 return "Incoming";
432 } else {
433 return "Outgoing";
434 }
435}
436
437std::string GetDirectionAsShortString(PacketDirection direction) {
438 if (direction == kIncomingPacket) {
439 return "In";
440 } else {
441 return "Out";
442 }
443}
444
terelius54ce6802016-07-13 06:44:41 -0700445} // namespace
446
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200447EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log,
448 bool normalize_time)
449 : parsed_log_(log),
450 window_duration_(250000),
451 step_(10000),
452 normalize_time_(normalize_time) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200453 begin_time_ = parsed_log_.first_timestamp();
454 end_time_ = parsed_log_.last_timestamp();
455 if (end_time_ < begin_time_) {
456 RTC_LOG(LS_WARNING) << "No useful events in the log.";
457 begin_time_ = end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000458 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200459 call_duration_s_ = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200460
461 const auto& log_start_events = parsed_log_.start_log_events();
462 const auto& log_end_events = parsed_log_.stop_log_events();
463 auto start_iter = log_start_events.begin();
464 auto end_iter = log_end_events.begin();
465 while (start_iter != log_start_events.end()) {
466 int64_t start = start_iter->log_time_us();
467 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200468 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200469 if (start_iter != log_start_events.end())
470 next_start.emplace(start_iter->log_time_us());
471 if (end_iter != log_end_events.end() &&
472 end_iter->log_time_us() <=
473 next_start.value_or(std::numeric_limits<int64_t>::max())) {
474 int64_t end = end_iter->log_time_us();
475 RTC_DCHECK_LE(start, end);
476 log_segments_.push_back(std::make_pair(start, end));
477 ++end_iter;
478 } else {
479 // we're missing an end event. Assume that it occurred just before the
480 // next start.
481 log_segments_.push_back(
482 std::make_pair(start, next_start.value_or(end_time_)));
483 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700484 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100485 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200486 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700487}
488
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200489class BitrateObserver : public RemoteBitrateObserver {
Stefan Holmer13181032016-07-29 14:48:54 +0200490 public:
491 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
492
Sebastian Jansson5c94f552018-10-15 18:46:51 +0200493 void Update(NetworkControlUpdate update) {
494 if (update.target_rate) {
495 last_bitrate_bps_ = update.target_rate->target_rate.bps();
496 bitrate_updated_ = true;
497 }
Stefan Holmer13181032016-07-29 14:48:54 +0200498 }
499
500 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
501 uint32_t bitrate) override {}
502
503 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
504 bool GetAndResetBitrateUpdated() {
505 bool bitrate_updated = bitrate_updated_;
506 bitrate_updated_ = false;
507 return bitrate_updated;
508 }
509
510 private:
511 uint32_t last_bitrate_bps_;
512 bool bitrate_updated_;
513};
514
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200515int64_t EventLogAnalyzer::ToCallTimeUs(int64_t timestamp) const {
516 int64_t begin_time = 0;
517 if (normalize_time_) {
518 begin_time = begin_time_;
519 }
520 return timestamp - begin_time;
521}
522
523float EventLogAnalyzer::ToCallTimeSec(int64_t timestamp) const {
524 return static_cast<float>(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100525}
526
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200527void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700528 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200529 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
530 // Filter on SSRC.
531 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700532 continue;
terelius54ce6802016-07-13 06:44:41 -0700533 }
terelius54ce6802016-07-13 06:44:41 -0700534
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200535 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
536 LineStyle::kBar);
537 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200538 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200539 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200540 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
541 return this->ToCallTimeSec(packet.log_time_us());
542 };
543 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
544 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700545 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700546 }
547
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200548 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
549 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700550 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
551 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200552 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700553}
554
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200555template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700556void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700557 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200558 const IterableType& packets,
559 const std::string& label) {
560 TimeSeries time_series(label, LineStyle::kStep);
561 for (size_t i = 0; i < packets.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200562 float x = ToCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200563 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700564 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200565 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700566}
567
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200568void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
569 Plot* plot) {
570 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
571 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
572 continue;
573 std::string label =
574 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
575 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
576 }
577 std::string label =
578 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
579 if (direction == kIncomingPacket) {
580 CreateAccumulatedPacketsTimeSeries(
581 plot, parsed_log_.incoming_rtcp_packets(), label);
582 } else {
583 CreateAccumulatedPacketsTimeSeries(
584 plot, parsed_log_.outgoing_rtcp_packets(), label);
585 }
philipelccd74892016-09-05 02:46:25 -0700586
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200587 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
588 kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700589 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200590 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
591 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700592}
593
terelius54ce6802016-07-13 06:44:41 -0700594// For each SSRC, plot the time between the consecutive playouts.
595void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200596 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
597 uint32_t ssrc = playout_stream.first;
598 if (!MatchingSsrc(ssrc, desired_ssrc_))
599 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200600 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200601 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200602 for (const auto& playout_event : playout_stream.second) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200603 float x = ToCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200604 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200605 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200606 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200607 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200608 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700609 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200610 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700611 }
612
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200613 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
614 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700615 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
616 kTopMargin);
617 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700618}
619
ivocaac9d6f2016-09-22 07:01:47 -0700620// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200621void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
622 Plot* plot) {
623 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
624 if (!IsAudioSsrc(direction, stream.ssrc))
625 continue;
626 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
627 LineStyle::kLine);
628 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700629 if (packet.header.extension.hasAudioLevel) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200630 float x = ToCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700631 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
632 // Here we convert it to dBov.
633 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200634 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700635 }
636 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200637 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700638 }
639
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200640 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
641 kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200642 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200643 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700644}
645
terelius54ce6802016-07-13 06:44:41 -0700646// For each SSRC, plot the time between the consecutive playouts.
647void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200648 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
649 // Filter on SSRC.
650 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700651 continue;
terelius54ce6802016-07-13 06:44:41 -0700652 }
terelius54ce6802016-07-13 06:44:41 -0700653
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200654 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
655 LineStyle::kBar);
656 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
657 const LoggedRtpPacketIncoming& new_packet) {
658 int64_t diff =
659 WrappingDifference(new_packet.rtp.header.sequenceNumber,
660 old_packet.rtp.header.sequenceNumber, 1ul << 16);
661 return diff;
662 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200663 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
664 return this->ToCallTimeSec(packet.log_time_us());
665 };
666 ProcessPairs<LoggedRtpPacketIncoming, float>(
667 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
668 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700669 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700670 }
671
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200672 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
673 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700674 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
675 kTopMargin);
676 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700677}
678
Stefan Holmer99f8e082016-09-09 13:37:50 +0200679void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200680 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
681 const std::vector<LoggedRtpPacketIncoming>& packets =
682 stream.incoming_packets;
683 // Filter on SSRC.
684 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200685 continue;
686 }
687
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200688 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
689 LineStyle::kLine, PointStyle::kHighlight);
690 // TODO(terelius): Should the window and step size be read from the class
691 // instead?
692 const int64_t kWindowUs = 1000000;
693 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100694 SeqNumUnwrapper<uint16_t> unwrapper_;
695 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800696 size_t window_index_begin = 0;
697 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200698 uint64_t highest_seq_number =
699 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
700 uint64_t highest_prior_seq_number =
701 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800702
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200703 for (int64_t t = begin_time_; t < end_time_ + kStep; t += kStep) {
704 while (window_index_end < packets.size() &&
705 packets[window_index_end].rtp.log_time_us() < t) {
706 uint64_t sequence_number = unwrapper_.Unwrap(
707 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800708 highest_seq_number = std::max(highest_seq_number, sequence_number);
709 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200710 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200711 while (window_index_begin < packets.size() &&
712 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
713 uint64_t sequence_number = prior_unwrapper_.Unwrap(
714 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800715 highest_prior_seq_number =
716 std::max(highest_prior_seq_number, sequence_number);
717 ++window_index_begin;
718 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200719 float x = ToCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200720 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800721 if (expected_packets > 0) {
722 int64_t received_packets = window_index_end - window_index_begin;
723 int64_t lost_packets = expected_packets - received_packets;
724 float y = static_cast<float>(lost_packets) / expected_packets * 100;
725 time_series.points.emplace_back(x, y);
726 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200727 }
philipel35ba9bd2017-04-19 05:58:51 -0700728 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200729 }
730
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200731 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
732 kLeftMargin, kRightMargin);
Stefan Holmer99f8e082016-09-09 13:37:50 +0200733 plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
734 kTopMargin);
735 plot->SetTitle("Estimated incoming loss rate");
736}
737
terelius2ee076d2017-08-15 02:04:02 -0700738void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100739 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200740 // Filter on SSRC.
741 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200742 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700743 continue;
744 }
terelius54ce6802016-07-13 06:44:41 -0700745
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100746 const std::vector<LoggedRtpPacketIncoming>& packets =
747 stream.incoming_packets;
748 if (packets.size() < 100) {
749 RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
750 << packets.size() << " packets in the stream.";
751 continue;
752 }
753 int64_t end_time_us = log_segments_.empty()
754 ? std::numeric_limits<int64_t>::max()
755 : log_segments_.front().second;
756 absl::optional<uint32_t> estimated_frequency =
757 EstimateRtpClockFrequency(packets, end_time_us);
758 if (!estimated_frequency)
759 continue;
760 const double frequency_hz = *estimated_frequency;
761 if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) {
762 RTC_LOG(LS_WARNING)
763 << "Video stream should use a 90 kHz clock but appears to use "
764 << frequency_hz / 1000 << ". Discarding.";
765 continue;
766 }
767
768 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
769 return this->ToCallTimeSec(packet.log_time_us());
770 };
771 auto ToNetworkDelay = [frequency_hz](
772 const LoggedRtpPacketIncoming& old_packet,
773 const LoggedRtpPacketIncoming& new_packet) {
774 return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
775 };
776
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200777 TimeSeries capture_time_data(
778 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
779 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100780 AccumulatePairs<LoggedRtpPacketIncoming, double>(
781 ToCallTime, ToNetworkDelay, packets, &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700782 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700783
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200784 TimeSeries send_time_data(
785 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
786 LineStyle::kLine);
Bjorn Terelius6c373cc2018-11-01 14:31:10 +0100787 AccumulatePairs<LoggedRtpPacketIncoming, double>(
788 ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
789 plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700790 }
791
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200792 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
793 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700794 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
795 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700796 plot->SetTitle("Network latency (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700797}
798
tereliusf736d232016-08-04 10:00:11 -0700799// Plot the fraction of packets lost (as perceived by the loss-based BWE).
800void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100801 TimeSeries time_series("Fraction lost", LineStyle::kLine,
802 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200803 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200804 float x = ToCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200805 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700806 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700807 }
tereliusf736d232016-08-04 10:00:11 -0700808
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200809 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200810 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
811 kLeftMargin, kRightMargin);
tereliusf736d232016-08-04 10:00:11 -0700812 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
813 kTopMargin);
814 plot->SetTitle("Reported packet loss");
815}
816
terelius54ce6802016-07-13 06:44:41 -0700817// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200818void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
819 // TODO(terelius): This could be provided by the parser.
820 std::multimap<int64_t, size_t> packets_in_order;
821 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
822 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
823 packets_in_order.insert(
824 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700825 }
826
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200827 auto window_begin = packets_in_order.begin();
828 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700829 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700830
831 // Calculate a moving average of the bitrate and store in a TimeSeries.
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100832 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200833 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
834 while (window_end != packets_in_order.end() && window_end->first < time) {
835 bytes_in_window += window_end->second;
836 ++window_end;
terelius54ce6802016-07-13 06:44:41 -0700837 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200838 while (window_begin != packets_in_order.end() &&
839 window_begin->first < time - window_duration_) {
840 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
841 bytes_in_window -= window_begin->second;
842 ++window_begin;
843 }
844 float window_duration_in_seconds =
845 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200846 float x = ToCallTimeSec(time);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200847 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
848 bitrate_series.points.emplace_back(x, y);
849 }
850 plot->AppendTimeSeries(std::move(bitrate_series));
851
852 // Overlay the outgoing REMB over incoming bitrate.
853 TimeSeries remb_series("Remb", LineStyle::kStep);
854 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200855 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200856 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
857 remb_series.points.emplace_back(x, y);
858 }
859 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
860
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200861 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
862 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200863 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
864 plot->SetTitle("Incoming RTP bitrate");
865}
866
867// Plot the total bandwidth used by all RTP streams.
868void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
869 bool show_detector_state,
870 bool show_alr_state) {
871 // TODO(terelius): This could be provided by the parser.
872 std::multimap<int64_t, size_t> packets_in_order;
873 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
874 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
875 packets_in_order.insert(
876 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
877 }
878
879 auto window_begin = packets_in_order.begin();
880 auto window_end = packets_in_order.begin();
881 size_t bytes_in_window = 0;
882
883 // Calculate a moving average of the bitrate and store in a TimeSeries.
884 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
885 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
886 while (window_end != packets_in_order.end() && window_end->first < time) {
887 bytes_in_window += window_end->second;
888 ++window_end;
889 }
890 while (window_begin != packets_in_order.end() &&
891 window_begin->first < time - window_duration_) {
892 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
893 bytes_in_window -= window_begin->second;
894 ++window_begin;
terelius54ce6802016-07-13 06:44:41 -0700895 }
896 float window_duration_in_seconds =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800897 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200898 float x = ToCallTimeSec(time);
terelius54ce6802016-07-13 06:44:41 -0700899 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
philipel35ba9bd2017-04-19 05:58:51 -0700900 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700901 }
philipel35ba9bd2017-04-19 05:58:51 -0700902 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700903
terelius8058e582016-07-25 01:32:41 -0700904 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200905 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
906 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200907 float x = ToCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200908 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
909 loss_series.points.emplace_back(x, y);
910 }
philipel10fc0e62017-04-11 01:50:23 -0700911
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200912 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
913 IntervalSeries overusing_series("Overusing", "#ff8e82",
914 IntervalSeries::kHorizontal);
915 IntervalSeries underusing_series("Underusing", "#5092fc",
916 IntervalSeries::kHorizontal);
917 IntervalSeries normal_series("Normal", "#c4ffc4",
918 IntervalSeries::kHorizontal);
919 IntervalSeries* last_series = &normal_series;
920 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700921
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200922 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700923
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200924 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200925 float x = ToCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200926 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700927
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200928 if (last_detector_state != delay_update.detector_state) {
929 last_series->intervals.emplace_back(last_detector_switch, x);
930 last_detector_state = delay_update.detector_state;
931 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700932
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200933 switch (delay_update.detector_state) {
934 case BandwidthUsage::kBwNormal:
935 last_series = &normal_series;
936 break;
937 case BandwidthUsage::kBwUnderusing:
938 last_series = &underusing_series;
939 break;
940 case BandwidthUsage::kBwOverusing:
941 last_series = &overusing_series;
942 break;
943 case BandwidthUsage::kLast:
944 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200945 }
946 }
philipel23c7f252017-07-14 06:30:03 -0700947
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200948 delay_series.points.emplace_back(x, y);
949 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200950
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200951 RTC_CHECK(last_series);
952 last_series->intervals.emplace_back(last_detector_switch, end_time_);
953
954 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
955 PointStyle::kHighlight);
956 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200957 float x = ToCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200958 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
959 created_series.points.emplace_back(x, y);
960 }
961
962 TimeSeries result_series("Probing results.", LineStyle::kNone,
963 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200964 for (auto& result : parsed_log_.bwe_probe_success_events()) {
965 float x = ToCallTimeSec(result.log_time_us());
966 float y = static_cast<float>(result.bitrate_bps) / 1000;
967 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200968 }
969
970 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
971 bool previously_in_alr = false;
972 int64_t alr_start = 0;
973 for (auto& alr : parsed_log_.alr_state_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200974 float y = ToCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200975 if (!previously_in_alr && alr.in_alr) {
976 alr_start = alr.log_time_us();
977 previously_in_alr = true;
978 } else if (previously_in_alr && !alr.in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200979 float x = ToCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100980 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200981 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +0000982 }
Björn Tereliusff612732018-04-25 14:23:01 +0000983 }
984
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200985 if (previously_in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200986 float x = ToCallTimeSec(alr_start);
987 float y = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200988 alr_state.intervals.emplace_back(x, y);
989 }
990
991 if (show_detector_state) {
992 plot->AppendIntervalSeries(std::move(overusing_series));
993 plot->AppendIntervalSeries(std::move(underusing_series));
994 plot->AppendIntervalSeries(std::move(normal_series));
995 }
996
997 if (show_alr_state) {
998 plot->AppendIntervalSeries(std::move(alr_state));
999 }
1000 plot->AppendTimeSeries(std::move(loss_series));
1001 plot->AppendTimeSeries(std::move(delay_series));
1002 plot->AppendTimeSeries(std::move(created_series));
1003 plot->AppendTimeSeries(std::move(result_series));
1004
1005 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001006 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001007 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001008 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001009 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001010 remb_series.points.emplace_back(x, y);
1011 }
1012 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1013
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001014 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1015 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001016 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001017 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001018}
1019
1020// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001021void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1022 Plot* plot) {
1023 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1024 // Filter on SSRC.
1025 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001026 continue;
terelius54ce6802016-07-13 06:44:41 -07001027 }
1028
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001029 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1030 LineStyle::kLine);
1031 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1032 return packet.total_length * 8.0 / 1000.0;
1033 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001034 auto ToCallTime = [this](int64_t time) {
1035 return this->ToCallTimeSec(time);
1036 };
terelius53dc23c2017-03-13 05:24:05 -07001037 MovingAverage<LoggedRtpPacket, double>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001038 ToCallTime, GetPacketSizeKilobits, stream.packet_view, begin_time_,
1039 end_time_, window_duration_, step_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001040 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001041 }
1042
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001043 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1044 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001045 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001046 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001047}
1048
Bjorn Terelius28db2662017-10-04 14:22:43 +02001049void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001050 using RtpPacketType = LoggedRtpPacketOutgoing;
1051 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001052
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001053 // TODO(terelius): This could be provided by the parser.
1054 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1055 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1056 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1057 outgoing_rtp.insert(
1058 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001059 }
1060
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001061 const std::vector<TransportFeedbackType>& incoming_rtcp =
1062 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001063
1064 SimulatedClock clock(0);
1065 BitrateObserver observer;
1066 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001067 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001068 PacedSender pacer(&clock, &packet_router, &null_event_log);
Sebastian Janssona39a0072018-10-15 20:59:07 +02001069 TransportFeedbackAdapter transport_feedback(&clock);
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001070 auto factory = GoogCcNetworkControllerFactory(&null_event_log);
1071 TimeDelta process_interval = factory.GetProcessInterval();
Stefan Holmer13181032016-07-29 14:48:54 +02001072 // TODO(holmer): Log the call config and use that here instead.
1073 static const uint32_t kDefaultStartBitrateBps = 300000;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001074 NetworkControllerConfig cc_config;
Sebastian Jansson78416b62018-10-18 13:08:17 +02001075 cc_config.constraints.at_time = Timestamp::us(clock.TimeInMicroseconds());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001076 cc_config.constraints.starting_rate = DataRate::bps(kDefaultStartBitrateBps);
1077 auto goog_cc = factory.Create(cc_config);
Stefan Holmer13181032016-07-29 14:48:54 +02001078
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001079 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1080 PointStyle::kHighlight);
1081 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1082 PointStyle::kHighlight);
1083 TimeSeries acked_estimate_time_series(
1084 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001085
1086 auto rtp_iterator = outgoing_rtp.begin();
1087 auto rtcp_iterator = incoming_rtcp.begin();
1088
1089 auto NextRtpTime = [&]() {
1090 if (rtp_iterator != outgoing_rtp.end())
1091 return static_cast<int64_t>(rtp_iterator->first);
1092 return std::numeric_limits<int64_t>::max();
1093 };
1094
1095 auto NextRtcpTime = [&]() {
1096 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001097 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001098 return std::numeric_limits<int64_t>::max();
1099 };
Bjorn Tereliusa728c912018-12-06 12:26:30 +01001100 int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
Stefan Holmer13181032016-07-29 14:48:54 +02001101
1102 auto NextProcessTime = [&]() {
1103 if (rtcp_iterator != incoming_rtcp.end() ||
1104 rtp_iterator != outgoing_rtp.end()) {
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001105 return next_process_time_us_;
Stefan Holmer13181032016-07-29 14:48:54 +02001106 }
1107 return std::numeric_limits<int64_t>::max();
1108 };
1109
Stefan Holmer492ee282016-10-27 17:19:20 +02001110 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001111#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1112 // The event_log_visualizer should normally not be compiled with
1113 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1114 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1115 // and piping the output to plot_dynamics.py can be used as a hack to get the
1116 // internal state of various BWE components. In this case, it is important
1117 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1118 // SendSideCongestionController since that would lead to duplicate outputs.
1119 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Karl Wiberg918f50c2018-07-05 11:40:33 +02001120 absl::make_unique<BitrateEstimator>());
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001121#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001122 int64_t time_us =
1123 std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
Stefan Holmer492ee282016-10-27 17:19:20 +02001124 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001125 while (time_us != std::numeric_limits<int64_t>::max()) {
1126 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
Bjorn Tereliusc60a7772018-12-05 21:15:30 +01001127 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1128 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1129 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1130 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1131 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
1132 transport_feedback.AddPacket(
1133 rtp_packet.rtp.header.ssrc,
1134 rtp_packet.rtp.header.extension.transportSequenceNumber,
1135 rtp_packet.rtp.total_length, PacedPacketInfo());
1136 rtc::SentPacket sent_packet(
1137 rtp_packet.rtp.header.extension.transportSequenceNumber,
1138 rtp_packet.rtp.log_time_us() / 1000);
1139 auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1140 if (sent_msg)
1141 observer.Update(goog_cc->OnSentPacket(*sent_msg));
1142 }
1143 ++rtp_iterator;
1144 }
Stefan Holmer13181032016-07-29 14:48:54 +02001145 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001146 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001147
1148 auto feedback_msg = transport_feedback.ProcessTransportFeedback(
1149 rtcp_iterator->transport_feedback);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001150 absl::optional<uint32_t> bitrate_bps;
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001151 if (feedback_msg) {
1152 observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
1153 std::vector<PacketFeedback> feedback =
1154 transport_feedback.GetTransportFeedbackVector();
1155 SortPacketFeedbackVector(&feedback);
1156 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001157#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001158 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001159#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001160 for (const PacketFeedback& packet : feedback)
1161 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1162 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
1163 }
Stefan Holmer13181032016-07-29 14:48:54 +02001164 }
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001165
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001166 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001167 float y = bitrate_bps.value_or(0) / 1000;
1168 acked_time_series.points.emplace_back(x, y);
1169#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1170 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1171 acked_estimate_time_series.points.emplace_back(x, y);
1172#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001173 ++rtcp_iterator;
1174 }
stefanc3de0332016-08-02 07:22:17 -07001175 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1176 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Sebastian Jansson5c94f552018-10-15 18:46:51 +02001177 ProcessInterval msg;
1178 msg.at_time = Timestamp::us(clock.TimeInMicroseconds());
1179 observer.Update(goog_cc->OnProcessInterval(msg));
1180 next_process_time_us_ += process_interval.us();
stefanc3de0332016-08-02 07:22:17 -07001181 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001182 if (observer.GetAndResetBitrateUpdated() ||
1183 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001184 uint32_t y = observer.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001185 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001186 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001187 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001188 }
1189 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1190 }
1191 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001192 plot->AppendTimeSeries(std::move(time_series));
1193 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001194 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001195
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001196 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1197 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001198 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001199 plot->SetTitle("Simulated send-side BWE behavior");
1200}
1201
1202void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001203 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001204 class RembInterceptingPacketRouter : public PacketRouter {
1205 public:
1206 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1207 uint32_t bitrate_bps) override {
1208 last_bitrate_bps_ = bitrate_bps;
1209 bitrate_updated_ = true;
1210 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1211 }
1212 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1213 bool GetAndResetBitrateUpdated() {
1214 bool bitrate_updated = bitrate_updated_;
1215 bitrate_updated_ = false;
1216 return bitrate_updated;
1217 }
1218
1219 private:
1220 uint32_t last_bitrate_bps_;
1221 bool bitrate_updated_;
1222 };
1223
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001224 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001225
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001226 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1227 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1228 for (const auto& rtp_packet : stream.incoming_packets)
1229 incoming_rtp.insert(
1230 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001231 }
1232 }
1233
1234 SimulatedClock clock(0);
1235 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001236 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001237 // Is this intentional?
1238 ReceiveSideCongestionController rscc(&clock, &packet_router);
1239 // TODO(holmer): Log the call config and use that here instead.
1240 // static const uint32_t kDefaultStartBitrateBps = 300000;
1241 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1242
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001243 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1244 PointStyle::kHighlight);
1245 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001246
1247 RateStatistics acked_bitrate(250, 8000);
1248 int64_t last_update_us = 0;
1249 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001250 const RtpPacketType& packet = *kv.second;
1251 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1252 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1253 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001254 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001255 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001256 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001257 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001258 if (bitrate_bps) {
1259 uint32_t y = *bitrate_bps / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001260 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001261 acked_time_series.points.emplace_back(x, y);
1262 }
1263 if (packet_router.GetAndResetBitrateUpdated() ||
1264 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1265 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001266 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001267 time_series.points.emplace_back(x, y);
1268 last_update_us = clock.TimeInMicroseconds();
1269 }
1270 }
1271 // Add the data set to the plot.
1272 plot->AppendTimeSeries(std::move(time_series));
1273 plot->AppendTimeSeries(std::move(acked_time_series));
1274
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001275 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1276 kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001277 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1278 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001279}
1280
tereliuse34c19c2016-08-15 08:47:14 -07001281void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001282 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1283 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001284 TimeSeries time_series("Network delay", LineStyle::kLine,
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001285 PointStyle::kHighlight);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001286 int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1287 int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
stefanc3de0332016-08-02 07:22:17 -07001288
stefana0a8ed72017-09-06 02:06:32 -07001289 int64_t prev_y = 0;
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001290 for (auto packet : GetNetworkTrace(parsed_log_)) {
1291 if (packet.arrival_time_ms == PacketFeedback::kNotReceived)
1292 continue;
1293 float x = ToCallTimeSec(1000 * packet.feedback_arrival_time_ms);
1294 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1295 late_feedback_series.points.emplace_back(x, prev_y);
1296 continue;
stefanc3de0332016-08-02 07:22:17 -07001297 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001298 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1299 prev_y = y;
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001300 int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1301 min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1302 min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001303 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001304 }
Christoffer Rodbro89f64d32018-09-27 14:29:35 +02001305
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001306 // We assume that the base network delay (w/o queues) is equal to half
1307 // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1308 // observed 1-ways delay and add half the minumum RTT.
1309 const int64_t estimated_clock_offset_ms =
1310 min_send_receive_diff_ms - min_rtt_ms / 2;
stefanc3de0332016-08-02 07:22:17 -07001311 for (TimeSeriesPoint& point : time_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001312 point.y -= estimated_clock_offset_ms;
stefana0a8ed72017-09-06 02:06:32 -07001313 for (TimeSeriesPoint& point : late_feedback_series.points)
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001314 point.y -= estimated_clock_offset_ms;
1315
stefanc3de0332016-08-02 07:22:17 -07001316 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001317 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1318 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001319
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001320 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1321 kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001322 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
Bjorn Terelius57ba7e12018-10-25 15:31:35 +02001323 plot->SetTitle("Network delay (based on per-packet feedback)");
stefanc3de0332016-08-02 07:22:17 -07001324}
stefan08383272016-12-20 08:51:52 -08001325
Bjorn Terelius0295a962017-10-25 17:42:41 +02001326void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001327 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1328 const std::vector<LoggedRtpPacketOutgoing>& packets =
1329 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001330
1331 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001332 RTC_LOG(LS_WARNING)
1333 << "Can't estimate a the RTP clock frequency or the "
1334 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001335 continue;
1336 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001337 int64_t end_time_us = log_segments_.empty()
1338 ? std::numeric_limits<int64_t>::max()
1339 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001340 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001341 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001342 if (!estimated_frequency)
1343 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001344 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1345 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001346 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001347 << "Video stream should use a 90 kHz clock but appears to use "
1348 << *estimated_frequency / 1000 << ". Discarding.";
1349 continue;
1350 }
1351
1352 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001353 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001354 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001355 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001356 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1357 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001358 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1359 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1360 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001361 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001362 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001363 first_capture_timestamp) /
1364 *estimated_frequency * 1000;
1365 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001366 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1367 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001368 float x = ToCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001369 float y = send_time_ms - capture_time_ms;
1370 pacer_delay_series.points.emplace_back(x, y);
1371 }
1372 plot->AppendTimeSeries(std::move(pacer_delay_series));
1373 }
1374
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001375 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1376 kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001377 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1378 plot->SetTitle(
1379 "Delay from capture to send time. (First packet normalized to 0.)");
1380}
1381
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001382void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1383 Plot* plot) {
1384 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1385 TimeSeries rtp_timestamps(
1386 GetStreamName(direction, stream.ssrc) + " capture-time",
1387 LineStyle::kLine, PointStyle::kHighlight);
1388 for (const auto& packet : stream.packet_view) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001389 float x = ToCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001390 float y = packet.header.timestamp;
1391 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001392 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001393 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001394
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001395 TimeSeries rtcp_timestamps(
1396 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1397 LineStyle::kLine, PointStyle::kHighlight);
1398 // TODO(terelius): Why only sender reports?
1399 const auto& sender_reports = parsed_log_.sender_reports(direction);
1400 for (const auto& rtcp : sender_reports) {
1401 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1402 continue;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001403 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001404 float y = rtcp.sr.rtp_timestamp();
1405 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001406 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001407 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001408 }
1409
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001410 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1411 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001412 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1413 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001414}
michaelt6e5b2192017-02-22 07:33:27 -08001415
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001416void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1417 PacketDirection direction,
1418 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1419 std::string title,
1420 std::string yaxis_label,
1421 Plot* plot) {
1422 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1423 const auto& sender_reports = parsed_log_.sender_reports(direction);
1424 for (const auto& rtcp : sender_reports) {
1425 float x = ToCallTimeSec(rtcp.log_time_us());
1426 uint32_t ssrc = rtcp.sr.sender_ssrc();
1427 for (const auto& block : rtcp.sr.report_blocks()) {
1428 float y = fy(block);
1429 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1430 bool inserted;
1431 if (sr_report_it == sr_reports_by_ssrc.end()) {
1432 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1433 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1434 LineStyle::kLine, PointStyle::kHighlight));
1435 }
1436 sr_report_it->second.points.emplace_back(x, y);
1437 }
1438 }
1439 for (auto& kv : sr_reports_by_ssrc) {
1440 plot->AppendTimeSeries(std::move(kv.second));
1441 }
1442
1443 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1444 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1445 for (const auto& rtcp : receiver_reports) {
1446 float x = ToCallTimeSec(rtcp.log_time_us());
1447 uint32_t ssrc = rtcp.rr.sender_ssrc();
1448 for (const auto& block : rtcp.rr.report_blocks()) {
1449 float y = fy(block);
1450 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1451 bool inserted;
1452 if (rr_report_it == rr_reports_by_ssrc.end()) {
1453 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1454 ssrc,
1455 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1456 LineStyle::kLine, PointStyle::kHighlight));
1457 }
1458 rr_report_it->second.points.emplace_back(x, y);
1459 }
1460 }
1461 for (auto& kv : rr_reports_by_ssrc) {
1462 plot->AppendTimeSeries(std::move(kv.second));
1463 }
1464
1465 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1466 kLeftMargin, kRightMargin);
1467 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1468 plot->SetTitle(title);
1469}
1470
michaelt6e5b2192017-02-22 07:33:27 -08001471void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001472 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1473 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001474 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001475 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001476 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001477 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001478 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001479 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001480 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001481 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1482 return this->ToCallTimeSec(packet.log_time_us());
1483 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001484 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001485 ToCallTime, GetAnaBitrateBps,
1486 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001487 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001488 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1489 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001490 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1491 plot->SetTitle("Reported audio encoder target bitrate");
1492}
1493
1494void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001495 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1496 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001497 auto GetAnaFrameLengthMs =
1498 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001499 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001500 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001501 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001502 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001503 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001504 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1505 return this->ToCallTimeSec(packet.log_time_us());
1506 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001507 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001508 ToCallTime, GetAnaFrameLengthMs,
1509 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001510 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001511 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1512 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001513 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1514 plot->SetTitle("Reported audio encoder frame length");
1515}
1516
terelius2ee076d2017-08-15 02:04:02 -07001517void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001518 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001519 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001520 auto GetAnaPacketLoss =
1521 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001522 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001523 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001524 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001525 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001526 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001527 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1528 return this->ToCallTimeSec(packet.log_time_us());
1529 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001530 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001531 ToCallTime, GetAnaPacketLoss,
1532 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001533 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001534 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1535 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001536 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1537 kTopMargin);
1538 plot->SetTitle("Reported audio encoder lost packets");
1539}
1540
1541void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001542 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1543 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001544 auto GetAnaFecEnabled =
1545 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001546 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001547 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001548 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001549 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001550 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001551 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1552 return this->ToCallTimeSec(packet.log_time_us());
1553 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001554 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001555 ToCallTime, GetAnaFecEnabled,
1556 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001557 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001558 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1559 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001560 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1561 plot->SetTitle("Reported audio encoder FEC");
1562}
1563
1564void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001565 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1566 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001567 auto GetAnaDtxEnabled =
1568 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001569 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001570 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001571 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001572 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001573 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001574 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1575 return this->ToCallTimeSec(packet.log_time_us());
1576 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001577 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001578 ToCallTime, GetAnaDtxEnabled,
1579 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001580 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001581 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1582 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001583 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1584 plot->SetTitle("Reported audio encoder DTX");
1585}
1586
1587void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001588 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1589 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001590 auto GetAnaNumChannels =
1591 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001592 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001593 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001594 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001595 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001596 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001597 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1598 return this->ToCallTimeSec(packet.log_time_us());
1599 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001600 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001601 ToCallTime, GetAnaNumChannels,
1602 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001603 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001604 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1605 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001606 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1607 kBottomMargin, kTopMargin);
1608 plot->SetTitle("Reported audio encoder number of channels");
1609}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001610
1611class NetEqStreamInput : public test::NetEqInput {
1612 public:
1613 // Does not take any ownership, and all pointers must refer to valid objects
1614 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001615 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001616 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001617 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001618 : packet_stream_(*packet_stream),
1619 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001620 output_events_it_(output_events->begin()),
1621 output_events_end_(output_events->end()),
1622 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001623 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001624 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001625 }
1626
Danil Chapovalov431abd92018-06-18 12:54:17 +02001627 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001628 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001629 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001630 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001631 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001632 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001633 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001634 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001635 }
1636
Danil Chapovalov431abd92018-06-18 12:54:17 +02001637 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001638 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001639 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001640 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001641 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001642 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001643 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001644 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001645 }
1646
1647 std::unique_ptr<PacketData> PopPacket() override {
1648 if (packet_stream_it_ == packet_stream_.end()) {
1649 return std::unique_ptr<PacketData>();
1650 }
1651 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001652 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001653 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001654
1655 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1656 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001657 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1658 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001659 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1660
1661 ++packet_stream_it_;
1662 return packet_data;
1663 }
1664
1665 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001666 if (output_events_it_ != output_events_end_) {
1667 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001668 }
1669 }
1670
1671 bool ended() const override { return !NextEventTime(); }
1672
Danil Chapovalov431abd92018-06-18 12:54:17 +02001673 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001674 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001675 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001676 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001677 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001678 }
1679
1680 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001681 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1682 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001683 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1684 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001685 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001686};
1687
1688namespace {
1689// Creates a NetEq test object and all necessary input and output helpers. Runs
1690// the test and returns the NetEqDelayAnalyzer object that was used to
1691// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001692std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001693 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001694 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001695 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001696 const std::string& replacement_file_name,
1697 int file_sample_rate_hz) {
1698 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001699 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001700
1701 constexpr int kReplacementPt = 127;
1702 std::set<uint8_t> cn_types;
1703 std::set<uint8_t> forbidden_types;
1704 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1705 cn_types, forbidden_types));
1706
1707 NetEq::Config config;
1708 config.max_packets_in_buffer = 200;
1709 config.enable_fast_accelerate = true;
1710
1711 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1712
1713 test::NetEqTest::DecoderMap codecs;
1714
1715 // Create a "replacement decoder" that produces the decoded audio by reading
1716 // from a file rather than from the encoded payloads.
1717 std::unique_ptr<test::ResampleInputAudioFile> replacement_file(
1718 new test::ResampleInputAudioFile(replacement_file_name,
1719 file_sample_rate_hz));
1720 replacement_file->set_output_rate_hz(48000);
1721 std::unique_ptr<AudioDecoder> replacement_decoder(
1722 new test::FakeDecodeFromFile(std::move(replacement_file), 48000, false));
1723 test::NetEqTest::ExtDecoderMap ext_codecs;
1724 ext_codecs[kReplacementPt] = {replacement_decoder.get(),
1725 NetEqDecoder::kDecoderArbitrary,
1726 "replacement codec"};
1727
1728 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1729 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001730 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1731 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001732 test::DefaultNetEqTestErrorCallback error_cb;
1733 test::NetEqTest::Callbacks callbacks;
1734 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001735 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1736 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001737
Ivo Creusen2db46b02018-12-14 16:49:12 +01001738 test::NetEqTest test(config, codecs, ext_codecs, nullptr, std::move(input),
henrik.lundin3c938fc2017-06-14 06:09:58 -07001739 std::move(output), callbacks);
1740 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001741 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001742}
1743} // namespace
1744
Minyue Lic6ff7572018-05-04 09:46:44 +02001745EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001746 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001747 int file_sample_rate_hz) const {
1748 NetEqStatsGetterMap neteq_stats;
1749
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001750 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001751 const uint32_t ssrc = stream.ssrc;
1752 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1753 continue;
1754 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1755 &stream.incoming_packets;
1756 if (audio_packets == nullptr) {
1757 // No incoming audio stream found.
1758 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001759 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001760
Minyue Li27e2b7d2018-05-07 15:20:24 +02001761 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1762
1763 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1764 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1765 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1766 // Could not find output events with SSRC matching the input audio stream.
1767 // Using the first available stream of output events.
1768 output_events_it = parsed_log_.audio_playout_events().cbegin();
1769 }
1770
Danil Chapovalov431abd92018-06-18 12:54:17 +02001771 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001772 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001773 ? absl::nullopt
1774 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001775
1776 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1777 audio_packets, &output_events_it->second, end_time_ms,
1778 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001779 }
1780
Minyue Lic6ff7572018-05-04 09:46:44 +02001781 return neteq_stats;
1782}
1783
Minyue Lic97933f2018-08-10 12:51:15 +02001784// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1785// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001786void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001787 uint32_t ssrc,
1788 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001789 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001790 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1791 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1792 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1793 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1794
Minyue Li01d2a672018-06-21 21:17:19 +02001795 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001796 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1797 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001798
Minyue Lic97933f2018-08-10 12:51:15 +02001799 TimeSeries time_series_packet_arrival("packet arrival delay",
1800 LineStyle::kLine);
1801 TimeSeries time_series_relative_packet_arrival(
1802 "Relative packet arrival delay", LineStyle::kLine);
1803 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
1804 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
1805 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02001806
1807 for (const auto& data : arrival_delay_ms) {
1808 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1809 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001810 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001811 }
1812 for (const auto& data : corrected_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_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02001816 TimeSeriesPoint(x, y));
1817 }
1818 for (const auto& data : playout_delay_ms) {
1819 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1820 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001821 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001822 }
1823 for (const auto& data : target_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_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001827 }
1828
Minyue Lic97933f2018-08-10 12:51:15 +02001829 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
1830 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
1831 plot->AppendTimeSeries(std::move(time_series_play_time));
1832 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001833
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001834 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1835 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001836 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
1837 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001838 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
1839}
1840
Minyue Lic9ac93f2018-06-26 13:01:32 +02001841template <typename NetEqStatsType>
1842void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001843 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02001844 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
1845 const test::NetEqStatsGetter*)> data_extractor,
1846 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001847 const std::string& plot_name,
1848 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001849 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001850
1851 for (const auto& st : neteq_stats) {
1852 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02001853 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
1854 data_extractor(st.second.get());
1855 for (const auto& data : *data_vector) {
1856 const float time = ToCallTimeSec(data.first * 1000); // ms to us.
1857 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001858 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02001859 }
1860 }
1861
1862 for (auto& series : time_series) {
1863 series.second.label = GetStreamName(kIncomingPacket, series.first);
1864 series.second.line_style = LineStyle::kLine;
1865 plot->AppendTimeSeries(std::move(series.second));
1866 }
1867
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001868 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1869 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001870 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001871 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001872}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001873
Minyue Lic9ac93f2018-06-26 13:01:32 +02001874void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
1875 const NetEqStatsGetterMap& neteq_stats,
1876 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
1877 const std::string& plot_name,
1878 Plot* plot) const {
1879 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
1880 neteq_stats,
1881 [](const test::NetEqStatsGetter* stats_getter) {
1882 return stats_getter->stats();
1883 },
1884 stats_extractor, plot_name, plot);
1885}
1886
1887void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
1888 const NetEqStatsGetterMap& neteq_stats,
1889 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
1890 const std::string& plot_name,
1891 Plot* plot) const {
1892 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
1893 neteq_stats,
1894 [](const test::NetEqStatsGetter* stats_getter) {
1895 return stats_getter->lifetime_stats();
1896 },
1897 stats_extractor, plot_name, plot);
1898}
1899
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001900void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1901 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001902 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001903 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1904 configs_by_cp_id.end()) {
1905 const std::string candidate_pair_desc =
1906 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001907 configs_by_cp_id[config.candidate_pair_id] =
1908 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1909 candidate_pair_desc,
1910 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001911 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1912 candidate_pair_desc;
1913 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001914 float x = ToCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001915 float y = static_cast<float>(config.type);
1916 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1917 }
1918
1919 // TODO(qingsi): There can be a large number of candidate pairs generated by
1920 // certain calls and the frontend cannot render the chart in this case due to
1921 // the failure of generating a palette with the same number of colors.
1922 for (auto& kv : configs_by_cp_id) {
1923 plot->AppendTimeSeries(std::move(kv.second));
1924 }
1925
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001926 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1927 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001928 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
1929 kTopMargin);
1930 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1931}
1932
1933std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1934 uint32_t candidate_pair_id) {
1935 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1936 candidate_pair_desc_by_id_.end()) {
1937 return candidate_pair_desc_by_id_[candidate_pair_id];
1938 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001939 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001940 // TODO(qingsi): Add the handling of the "Updated" config event after the
1941 // visualization of property change for candidate pairs is introduced.
1942 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1943 candidate_pair_desc_by_id_.end()) {
1944 const std::string candidate_pair_desc =
1945 GetCandidatePairLogDescriptionAsString(config);
1946 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1947 candidate_pair_desc;
1948 }
1949 }
1950 return candidate_pair_desc_by_id_[candidate_pair_id];
1951}
1952
1953void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1954 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001955 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001956 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1957 checks_by_cp_id.end()) {
1958 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08001959 "[" + std::to_string(event.candidate_pair_id) + "]" +
1960 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001961 LineStyle::kNone, PointStyle::kHighlight);
1962 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001963 float x = ToCallTimeSec(event.log_time_us());
Zach Stein6353fbc2018-12-03 14:35:59 -08001964 constexpr int kIceCandidatePairEventTypeOffset =
1965 static_cast<int>(IceCandidatePairConfigType::kNumValues);
1966 float y = static_cast<float>(event.type) + kIceCandidatePairEventTypeOffset;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001967 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1968 }
1969
1970 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1971 for (auto& kv : checks_by_cp_id) {
1972 plot->AppendTimeSeries(std::move(kv.second));
1973 }
1974
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001975 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1976 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001977 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
1978 kTopMargin);
1979 plot->SetTitle("[IceEventLog] ICE connectivity checks");
1980}
1981
Zach Stein10a58012018-12-07 12:26:28 -08001982void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
1983 TimeSeries states("DTLS Transport State", LineStyle::kNone,
1984 PointStyle::kHighlight);
1985 for (const auto& event : parsed_log_.dtls_transport_states()) {
1986 float x = ToCallTimeSec(event.log_time_us());
1987 float y = static_cast<float>(event.dtls_transport_state);
1988 states.points.emplace_back(x, y);
1989 }
1990 plot->AppendTimeSeries(std::move(states));
1991 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1992 kLeftMargin, kRightMargin);
1993 plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
1994 "Numeric Transport State", kBottomMargin, kTopMargin);
1995 plot->SetTitle("DTLS Transport State");
1996}
1997
1998void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
1999 TimeSeries writable("DTLS Writable", LineStyle::kNone,
2000 PointStyle::kHighlight);
2001 for (const auto& event : parsed_log_.dtls_writable_states()) {
2002 float x = ToCallTimeSec(event.log_time_us());
2003 float y = static_cast<float>(event.writable);
2004 writable.points.emplace_back(x, y);
2005 }
2006 plot->AppendTimeSeries(std::move(writable));
2007 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
2008 kLeftMargin, kRightMargin);
2009 plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
2010 plot->SetTitle("DTLS Writable State");
2011}
2012
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002013void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002014 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002015 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2016 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2017 }
2018 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2019 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2020 }
2021 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2022 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2023 }
2024 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2025 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2026 }
2027 for (const auto& alert : incoming_seq_num_jumps_) {
2028 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2029 }
2030 for (const auto& alert : incoming_capture_time_jumps_) {
2031 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2032 }
2033 for (const auto& alert : outgoing_seq_num_jumps_) {
2034 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2035 }
2036 for (const auto& alert : outgoing_capture_time_jumps_) {
2037 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2038 }
2039 for (const auto& alert : outgoing_high_loss_alerts_) {
2040 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002041 }
2042 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2043}
2044
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002045void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2046 // With 100 packets/s (~800kbps), false positives would require 10 s without
2047 // data.
2048 constexpr int64_t kMaxSeqNumJump = 1000;
2049 // With a 90 kHz clock, false positives would require 10 s without data.
2050 constexpr int64_t kMaxCaptureTimeJump = 900000;
2051
2052 int64_t end_time_us = log_segments_.empty()
2053 ? std::numeric_limits<int64_t>::max()
2054 : log_segments_.front().second;
2055
2056 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002057 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002058 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002059 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002060 // Check for gaps in sequence numbers and capture timestamps.
2061 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2062 for (const auto& packet : stream.packet_view) {
2063 if (packet.log_time_us() > end_time_us) {
2064 // Only process the first (LOG_START, LOG_END) segment.
2065 break;
2066 }
2067
2068 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2069 if (last_seq_num.has_value() &&
2070 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002071 Alert_SeqNumJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002072 packet.header.ssrc);
2073 }
2074 last_seq_num.emplace(seq_num);
2075
2076 int64_t capture_time =
2077 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2078 if (last_capture_time.has_value() &&
2079 std::abs(capture_time - last_capture_time.value()) >
2080 kMaxCaptureTimeJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002081 Alert_CaptureTimeJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002082 packet.header.ssrc);
2083 }
2084 last_capture_time.emplace(capture_time);
2085 }
2086 }
2087}
2088
2089void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2090 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2091 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2092 int64_t end_time_us = log_segments_.empty()
2093 ? std::numeric_limits<int64_t>::max()
2094 : log_segments_.front().second;
2095
2096 // TODO(terelius): The parser could provide a list of all packets, ordered
2097 // by time, for each direction.
2098 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2099 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2100 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2101 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2102 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002103 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002104 for (const auto& kv : rtp_in_direction) {
2105 int64_t timestamp = kv.first;
2106 if (timestamp > end_time_us) {
2107 // Only process the first (LOG_START, LOG_END) segment.
2108 break;
2109 }
2110 int64_t duration = timestamp - last_rtp_time.value_or(0);
2111 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2112 // No packet sent/received for more than 500 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002113 Alert_RtpLogTimeGap(direction, ToCallTimeSec(timestamp), duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002114 }
2115 last_rtp_time.emplace(timestamp);
2116 }
2117
Danil Chapovalov431abd92018-06-18 12:54:17 +02002118 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002119 if (direction == kIncomingPacket) {
2120 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2121 if (rtcp.log_time_us() > end_time_us) {
2122 // Only process the first (LOG_START, LOG_END) segment.
2123 break;
2124 }
2125 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2126 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2127 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002128 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002129 duration / 1000);
2130 }
2131 last_rtcp_time.emplace(rtcp.log_time_us());
2132 }
2133 } else {
2134 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2135 if (rtcp.log_time_us() > end_time_us) {
2136 // Only process the first (LOG_START, LOG_END) segment.
2137 break;
2138 }
2139 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2140 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2141 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002142 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002143 duration / 1000);
2144 }
2145 last_rtcp_time.emplace(rtcp.log_time_us());
2146 }
2147 }
2148}
2149
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002150// TODO(terelius): Notifications could possibly be generated by the same code
2151// that produces the graphs. There is some code duplication that could be
2152// avoided, but that might be solved anyway when we move functionality from the
2153// analyzer to the parser.
2154void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002155 CreateStreamGapAlerts(kIncomingPacket);
2156 CreateStreamGapAlerts(kOutgoingPacket);
2157 CreateTransmissionGapAlerts(kIncomingPacket);
2158 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002159
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002160 int64_t end_time_us = log_segments_.empty()
2161 ? std::numeric_limits<int64_t>::max()
2162 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002163
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002164 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002165 // Loss feedback
2166 int64_t total_lost_packets = 0;
2167 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002168 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2169 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002170 // Only process the first (LOG_START, LOG_END) segment.
2171 break;
2172 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002173 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002174 bwe_update.expected_packets;
2175 total_lost_packets += lost_packets;
2176 total_expected_packets += bwe_update.expected_packets;
2177 }
2178 double avg_outgoing_loss =
2179 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002180 if (avg_outgoing_loss > kMaxLossFraction) {
2181 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002182 }
2183}
2184
terelius54ce6802016-07-13 06:44:41 -07002185} // namespace webrtc