blob: 145b2acae332742a341899b26519decdaa9cc1ce [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
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020020#include "call/audio_receive_stream.h"
21#include "call/audio_send_stream.h"
22#include "call/call.h"
23#include "call/video_receive_stream.h"
24#include "call/video_send_stream.h"
Mirko Bonadei71207422017-09-15 13:58:09 +020025#include "common_types.h" // NOLINT(build/include)
Elad Alon99a81b62017-09-21 10:25:29 +020026#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020027#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020028#include "modules/audio_coding/neteq/tools/audio_sink.h"
29#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
30#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
31#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
32#include "modules/audio_coding/neteq/tools/neteq_test.h"
33#include "modules/audio_coding/neteq/tools/resample_input_audio_file.h"
Danil Chapovalovbda50682018-02-14 09:08:28 +000034#include "modules/congestion_controller/acknowledged_bitrate_estimator.h"
35#include "modules/congestion_controller/bitrate_estimator.h"
Sebastian Jansson439f0bc2018-02-20 10:46:39 +010036#include "modules/congestion_controller/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020037#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020038#include "modules/congestion_controller/include/send_side_congestion_controller.h"
39#include "modules/include/module_common_types.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010040#include "modules/pacing/packet_router.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020041#include "modules/rtp_rtcp/include/rtp_rtcp.h"
42#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020043#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020044#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
45#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
46#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
47#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
48#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
49#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
50#include "modules/rtp_rtcp/source/rtp_utility.h"
51#include "rtc_base/checks.h"
52#include "rtc_base/format_macros.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020053#include "rtc_base/function_view.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020054#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020055#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020056#include "rtc_base/ptr_util.h"
57#include "rtc_base/rate_statistics.h"
terelius54ce6802016-07-13 06:44:41 -070058
Bjorn Terelius6984ad22017-10-24 12:19:45 +020059#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
60#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
61#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
62
tereliusdc35dcd2016-08-01 12:03:27 -070063namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070064
terelius54ce6802016-07-13 06:44:41 -070065namespace {
66
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080067const int kNumMicrosecsPerSec = 1000000;
68
elad.alonec304f92017-03-08 05:03:53 -080069void SortPacketFeedbackVector(std::vector<PacketFeedback>* vec) {
70 auto pred = [](const PacketFeedback& packet_feedback) {
71 return packet_feedback.arrival_time_ms == PacketFeedback::kNotReceived;
72 };
73 vec->erase(std::remove_if(vec->begin(), vec->end(), pred), vec->end());
74 std::sort(vec->begin(), vec->end(), PacketFeedbackComparator());
75}
76
terelius54ce6802016-07-13 06:44:41 -070077std::string SsrcToString(uint32_t ssrc) {
78 std::stringstream ss;
79 ss << "SSRC " << ssrc;
80 return ss.str();
81}
82
83// Checks whether an SSRC is contained in the list of desired SSRCs.
84// Note that an empty SSRC list matches every SSRC.
85bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
86 if (desired_ssrc.size() == 0)
87 return true;
88 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
89 desired_ssrc.end();
90}
91
92double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
93 // The timestamp is a fixed point representation with 6 bits for seconds
94 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080095 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
96 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070097 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080098 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -070099 return abs_send_time * kTimestampToMicroSec;
100}
101
102// Computes the difference |later| - |earlier| where |later| and |earlier|
103// are counters that wrap at |modulus|. The difference is chosen to have the
104// least absolute value. For example if |modulus| is 8, then the difference will
105// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
106// be in [-4, 4].
107int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
108 RTC_DCHECK_LE(1, modulus);
109 RTC_DCHECK_LT(later, modulus);
110 RTC_DCHECK_LT(earlier, modulus);
111 int64_t difference =
112 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
113 int64_t max_difference = modulus / 2;
114 int64_t min_difference = max_difference - modulus + 1;
115 if (difference > max_difference) {
116 difference -= modulus;
117 }
118 if (difference < min_difference) {
119 difference += modulus;
120 }
terelius6addf492016-08-23 17:34:07 -0700121 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100122 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
123 << " expected to be in the range ("
124 << min_difference / 2 << "," << max_difference / 2
125 << ") but is " << difference
126 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700127 }
terelius54ce6802016-07-13 06:44:41 -0700128 return difference;
129}
130
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200131// This is much more reliable for outgoing streams than for incoming streams.
132template <typename RtpPacketContainer>
133rtc::Optional<uint32_t> EstimateRtpClockFrequency(
134 const RtpPacketContainer& packets,
135 int64_t end_time_us) {
136 RTC_CHECK(packets.size() >= 2);
137 SeqNumUnwrapper<uint32_t> unwrapper;
138 uint64_t first_rtp_timestamp =
139 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
140 int64_t first_log_timestamp = packets[0].log_time_us();
141 uint64_t last_rtp_timestamp = first_rtp_timestamp;
142 int64_t last_log_timestamp = first_log_timestamp;
143 for (size_t i = 1; i < packets.size(); i++) {
144 if (packets[i].log_time_us() > end_time_us)
145 break;
146 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
147 last_log_timestamp = packets[i].log_time_us();
148 }
149 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
150 RTC_LOG(LS_WARNING)
151 << "Failed to estimate RTP clock frequency: Stream too short. ("
152 << packets.size() << " packets, "
153 << last_log_timestamp - first_log_timestamp << " us)";
154 return rtc::nullopt;
155 }
156 double duration =
157 static_cast<double>(last_log_timestamp - first_log_timestamp) /
158 kNumMicrosecsPerSec;
159 double estimated_frequency =
160 (last_rtp_timestamp - first_rtp_timestamp) / duration;
161 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
162 if (std::fabs(estimated_frequency - f) < 0.05 * f) {
163 return f;
164 }
165 }
166 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
167 << estimated_frequency
168 << "not close to any stardard RTP frequency.";
169 return rtc::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700170}
171
tereliusdc35dcd2016-08-01 12:03:27 -0700172constexpr float kLeftMargin = 0.01f;
173constexpr float kRightMargin = 0.02f;
174constexpr float kBottomMargin = 0.02f;
175constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700176
terelius53dc23c2017-03-13 05:24:05 -0700177rtc::Optional<double> NetworkDelayDiff_AbsSendTime(
178 const LoggedRtpPacket& old_packet,
179 const LoggedRtpPacket& new_packet) {
180 if (old_packet.header.extension.hasAbsoluteSendTime &&
181 new_packet.header.extension.hasAbsoluteSendTime) {
182 int64_t send_time_diff = WrappingDifference(
183 new_packet.header.extension.absoluteSendTime,
184 old_packet.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200185 int64_t recv_time_diff =
186 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700187 double delay_change_us =
188 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100189 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700190 } else {
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100191 return rtc::nullopt;
terelius6addf492016-08-23 17:34:07 -0700192 }
193}
194
terelius53dc23c2017-03-13 05:24:05 -0700195rtc::Optional<double> NetworkDelayDiff_CaptureTime(
196 const LoggedRtpPacket& old_packet,
197 const LoggedRtpPacket& new_packet) {
198 int64_t send_time_diff = WrappingDifference(
199 new_packet.header.timestamp, old_packet.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200200 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700201
202 const double kVideoSampleRate = 90000;
203 // TODO(terelius): We treat all streams as video for now, even though
204 // audio might be sampled at e.g. 16kHz, because it is really difficult to
205 // figure out the true sampling rate of a stream. The effect is that the
206 // delay will be scaled incorrectly for non-video streams.
207
208 double delay_change =
209 static_cast<double>(recv_time_diff) / 1000 -
210 static_cast<double>(send_time_diff) / kVideoSampleRate * 1000;
211 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100212 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
213 RTC_LOG(LS_WARNING) << "Old capture time " << old_packet.header.timestamp
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200214 << ", received time " << old_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100215 RTC_LOG(LS_WARNING) << "New capture time " << new_packet.header.timestamp
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200216 << ", received time " << 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 << " = "
222 << static_cast<double>(send_time_diff) /
223 kVideoSampleRate
224 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700225 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100226 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700227}
228
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200229// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700230// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200231template <typename DataType, typename IterableType>
232void ProcessPoints(rtc::FunctionView<rtc::Optional<float>(const DataType&)> f,
233 const IterableType& data_view,
234 int64_t begin_time,
235 TimeSeries* result) {
236 for (size_t i = 0; i < data_view.size(); i++) {
237 const DataType& elem = data_view[i];
238 float x = static_cast<float>(elem.log_time_us() - begin_time) /
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800239 kNumMicrosecsPerSec;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200240 rtc::Optional<float> y = f(elem);
terelius53dc23c2017-03-13 05:24:05 -0700241 if (y)
242 result->points.emplace_back(x, *y);
243 }
244}
245
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200246// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700247// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
248// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200249template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700250void ProcessPairs(
251 rtc::FunctionView<rtc::Optional<ResultType>(const DataType&,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200252 const DataType&)> f,
253 const IterableType& data,
254 int64_t begin_time,
terelius53dc23c2017-03-13 05:24:05 -0700255 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700256 for (size_t i = 1; i < data.size(); i++) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200257 float x = static_cast<float>(data[i].log_time_us() - begin_time) /
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800258 kNumMicrosecsPerSec;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200259 rtc::Optional<ResultType> y = f(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700260 if (y)
261 result->points.emplace_back(x, static_cast<float>(*y));
262 }
263}
264
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200265// For each element in data, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700266// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200267template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700268void AccumulatePoints(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200269 rtc::FunctionView<rtc::Optional<ResultType>(const DataType&)> f,
270 const IterableType& data,
271 int64_t begin_time,
terelius53dc23c2017-03-13 05:24:05 -0700272 TimeSeries* result) {
273 ResultType sum = 0;
274 for (size_t i = 0; i < data.size(); i++) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200275 float x = static_cast<float>(data[i].log_time_us() - begin_time) /
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800276 kNumMicrosecsPerSec;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200277 rtc::Optional<ResultType> y = f(data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700278 if (y) {
279 sum += *y;
280 result->points.emplace_back(x, static_cast<float>(sum));
281 }
282 }
283}
284
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200285// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700286// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
287// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200288template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700289void AccumulatePairs(
290 rtc::FunctionView<rtc::Optional<ResultType>(const DataType&,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200291 const DataType&)> f,
292 const IterableType& data,
293 int64_t begin_time,
terelius53dc23c2017-03-13 05:24:05 -0700294 TimeSeries* result) {
295 ResultType sum = 0;
296 for (size_t i = 1; i < data.size(); i++) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200297 float x = static_cast<float>(data[i].log_time_us() - begin_time) /
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800298 kNumMicrosecsPerSec;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200299 rtc::Optional<ResultType> y = f(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700300 if (y)
301 sum += *y;
302 result->points.emplace_back(x, static_cast<float>(sum));
tereliusccbbf8d2016-08-10 07:34:28 -0700303 }
304}
305
terelius6addf492016-08-23 17:34:07 -0700306// Calculates a moving average of |data| and stores the result in a TimeSeries.
307// A data point is generated every |step| microseconds from |begin_time|
308// to |end_time|. The value of each data point is the average of the data
309// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200310template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700311void MovingAverage(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200312 rtc::FunctionView<rtc::Optional<ResultType>(const DataType&)> f,
313 const IterableType& data_view,
314 int64_t begin_time,
315 int64_t end_time,
316 int64_t window_duration_us,
317 int64_t step,
318 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700319 size_t window_index_begin = 0;
320 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700321 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700322
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200323 for (int64_t t = begin_time; t < end_time + step; t += step) {
324 while (window_index_end < data_view.size() &&
325 data_view[window_index_end].log_time_us() < t) {
326 rtc::Optional<ResultType> value = f(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700327 if (value)
328 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700329 ++window_index_end;
330 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200331 while (window_index_begin < data_view.size() &&
332 data_view[window_index_begin].log_time_us() <
333 t - window_duration_us) {
334 rtc::Optional<ResultType> value = f(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700335 if (value)
336 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700337 ++window_index_begin;
338 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800339 float window_duration_s =
340 static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
341 float x = static_cast<float>(t - begin_time) / kNumMicrosecsPerSec;
terelius53dc23c2017-03-13 05:24:05 -0700342 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700343 result->points.emplace_back(x, y);
344 }
345}
346
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800347const char kUnknownEnumValue[] = "unknown";
348
349const char kIceCandidateTypeLocal[] = "local";
350const char kIceCandidateTypeStun[] = "stun";
351const char kIceCandidateTypePrflx[] = "prflx";
352const char kIceCandidateTypeRelay[] = "relay";
353
354const char kProtocolUdp[] = "udp";
355const char kProtocolTcp[] = "tcp";
356const char kProtocolSsltcp[] = "ssltcp";
357const char kProtocolTls[] = "tls";
358
359const char kAddressFamilyIpv4[] = "ipv4";
360const char kAddressFamilyIpv6[] = "ipv6";
361
362const char kNetworkTypeEthernet[] = "ethernet";
363const char kNetworkTypeLoopback[] = "loopback";
364const char kNetworkTypeWifi[] = "wifi";
365const char kNetworkTypeVpn[] = "vpn";
366const char kNetworkTypeCellular[] = "cellular";
367
368std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
369 switch (type) {
370 case webrtc::IceCandidateType::kLocal:
371 return kIceCandidateTypeLocal;
372 case webrtc::IceCandidateType::kStun:
373 return kIceCandidateTypeStun;
374 case webrtc::IceCandidateType::kPrflx:
375 return kIceCandidateTypePrflx;
376 case webrtc::IceCandidateType::kRelay:
377 return kIceCandidateTypeRelay;
378 default:
379 return kUnknownEnumValue;
380 }
381}
382
383std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
384 switch (protocol) {
385 case webrtc::IceCandidatePairProtocol::kUdp:
386 return kProtocolUdp;
387 case webrtc::IceCandidatePairProtocol::kTcp:
388 return kProtocolTcp;
389 case webrtc::IceCandidatePairProtocol::kSsltcp:
390 return kProtocolSsltcp;
391 case webrtc::IceCandidatePairProtocol::kTls:
392 return kProtocolTls;
393 default:
394 return kUnknownEnumValue;
395 }
396}
397
398std::string GetAddressFamilyAsString(
399 webrtc::IceCandidatePairAddressFamily family) {
400 switch (family) {
401 case webrtc::IceCandidatePairAddressFamily::kIpv4:
402 return kAddressFamilyIpv4;
403 case webrtc::IceCandidatePairAddressFamily::kIpv6:
404 return kAddressFamilyIpv6;
405 default:
406 return kUnknownEnumValue;
407 }
408}
409
410std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
411 switch (type) {
412 case webrtc::IceCandidateNetworkType::kEthernet:
413 return kNetworkTypeEthernet;
414 case webrtc::IceCandidateNetworkType::kLoopback:
415 return kNetworkTypeLoopback;
416 case webrtc::IceCandidateNetworkType::kWifi:
417 return kNetworkTypeWifi;
418 case webrtc::IceCandidateNetworkType::kVpn:
419 return kNetworkTypeVpn;
420 case webrtc::IceCandidateNetworkType::kCellular:
421 return kNetworkTypeCellular;
422 default:
423 return kUnknownEnumValue;
424 }
425}
426
427std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200428 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800429 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
430 // represents a pair of a local server-reflexive candidate on a WiFi network
431 // and a remote relay candidate using TCP as the relay protocol on a cell
432 // network, when the candidate pair communicates over UDP using IPv4.
433 std::stringstream ss;
434 std::string local_candidate_type =
435 GetIceCandidateTypeAsString(config.local_candidate_type);
436 std::string remote_candidate_type =
437 GetIceCandidateTypeAsString(config.remote_candidate_type);
438 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
439 local_candidate_type +=
440 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
441 }
442 ss << local_candidate_type << ":"
443 << GetNetworkTypeAsString(config.local_network_type) << ":"
444 << GetAddressFamilyAsString(config.local_address_family) << "->"
445 << remote_candidate_type << ":"
446 << GetAddressFamilyAsString(config.remote_address_family) << "@"
447 << GetProtocolAsString(config.candidate_pair_protocol);
448 return ss.str();
449}
450
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200451std::string GetDirectionAsString(PacketDirection direction) {
452 if (direction == kIncomingPacket) {
453 return "Incoming";
454 } else {
455 return "Outgoing";
456 }
457}
458
459std::string GetDirectionAsShortString(PacketDirection direction) {
460 if (direction == kIncomingPacket) {
461 return "In";
462 } else {
463 return "Out";
464 }
465}
466
terelius54ce6802016-07-13 06:44:41 -0700467} // namespace
468
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200469EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log)
terelius54ce6802016-07-13 06:44:41 -0700470 : parsed_log_(log), window_duration_(250000), step_(10000) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200471 begin_time_ = parsed_log_.first_timestamp();
472 end_time_ = parsed_log_.last_timestamp();
473 if (end_time_ < begin_time_) {
474 RTC_LOG(LS_WARNING) << "No useful events in the log.";
475 begin_time_ = end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000476 }
Björn Tereliusff612732018-04-25 14:23:01 +0000477 call_duration_s_ = ToCallTime(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200478
479 const auto& log_start_events = parsed_log_.start_log_events();
480 const auto& log_end_events = parsed_log_.stop_log_events();
481 auto start_iter = log_start_events.begin();
482 auto end_iter = log_end_events.begin();
483 while (start_iter != log_start_events.end()) {
484 int64_t start = start_iter->log_time_us();
485 ++start_iter;
486 rtc::Optional<int64_t> next_start;
487 if (start_iter != log_start_events.end())
488 next_start.emplace(start_iter->log_time_us());
489 if (end_iter != log_end_events.end() &&
490 end_iter->log_time_us() <=
491 next_start.value_or(std::numeric_limits<int64_t>::max())) {
492 int64_t end = end_iter->log_time_us();
493 RTC_DCHECK_LE(start, end);
494 log_segments_.push_back(std::make_pair(start, end));
495 ++end_iter;
496 } else {
497 // we're missing an end event. Assume that it occurred just before the
498 // next start.
499 log_segments_.push_back(
500 std::make_pair(start, next_start.value_or(end_time_)));
501 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700502 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100503 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
504 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700505}
506
Sebastian Janssone4be6da2018-02-15 16:51:41 +0100507class BitrateObserver : public NetworkChangedObserver,
Stefan Holmer13181032016-07-29 14:48:54 +0200508 public RemoteBitrateObserver {
509 public:
510 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
511
512 void OnNetworkChanged(uint32_t bitrate_bps,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200513 uint8_t fraction_lost,
minyue78b4d562016-11-30 04:47:39 -0800514 int64_t rtt_ms,
515 int64_t probing_interval_ms) override {
Stefan Holmer13181032016-07-29 14:48:54 +0200516 last_bitrate_bps_ = bitrate_bps;
517 bitrate_updated_ = true;
518 }
519
520 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
521 uint32_t bitrate) override {}
522
523 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
524 bool GetAndResetBitrateUpdated() {
525 bool bitrate_updated = bitrate_updated_;
526 bitrate_updated_ = false;
527 return bitrate_updated;
528 }
529
530 private:
531 uint32_t last_bitrate_bps_;
532 bool bitrate_updated_;
533};
534
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100535float EventLogAnalyzer::ToCallTime(int64_t timestamp) const {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800536 return static_cast<float>(timestamp - begin_time_) / kNumMicrosecsPerSec;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100537}
538
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200539void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700540 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200541 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
542 // Filter on SSRC.
543 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700544 continue;
terelius54ce6802016-07-13 06:44:41 -0700545 }
terelius54ce6802016-07-13 06:44:41 -0700546
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200547 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
548 LineStyle::kBar);
549 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
550 return rtc::Optional<float>(packet.total_length);
551 };
552 ProcessPoints<LoggedRtpPacket>(GetPacketSize, stream.packet_view,
553 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700554 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700555 }
556
tereliusdc35dcd2016-08-01 12:03:27 -0700557 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
558 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
559 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200560 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700561}
562
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200563template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700564void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700565 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200566 const IterableType& packets,
567 const std::string& label) {
568 TimeSeries time_series(label, LineStyle::kStep);
569 for (size_t i = 0; i < packets.size(); i++) {
570 float x = ToCallTime(packets[i].log_time_us());
571 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700572 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200573 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700574}
575
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200576void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
577 Plot* plot) {
578 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
579 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
580 continue;
581 std::string label =
582 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
583 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
584 }
585 std::string label =
586 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
587 if (direction == kIncomingPacket) {
588 CreateAccumulatedPacketsTimeSeries(
589 plot, parsed_log_.incoming_rtcp_packets(), label);
590 } else {
591 CreateAccumulatedPacketsTimeSeries(
592 plot, parsed_log_.outgoing_rtcp_packets(), label);
593 }
philipelccd74892016-09-05 02:46:25 -0700594
595 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
596 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200597 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
598 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700599}
600
terelius54ce6802016-07-13 06:44:41 -0700601// For each SSRC, plot the time between the consecutive playouts.
602void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200603 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
604 uint32_t ssrc = playout_stream.first;
605 if (!MatchingSsrc(ssrc, desired_ssrc_))
606 continue;
Minyue Li27e2b7d2018-05-07 15:20:24 +0200607 rtc::Optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200608 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200609 for (const auto& playout_event : playout_stream.second) {
610 float x = ToCallTime(playout_event.log_time_us());
611 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200612 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200613 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200614 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200615 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700616 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200617 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700618 }
619
tereliusdc35dcd2016-08-01 12:03:27 -0700620 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
621 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
622 kTopMargin);
623 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700624}
625
ivocaac9d6f2016-09-22 07:01:47 -0700626// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200627void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
628 Plot* plot) {
629 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
630 if (!IsAudioSsrc(direction, stream.ssrc))
631 continue;
632 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
633 LineStyle::kLine);
634 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700635 if (packet.header.extension.hasAudioLevel) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200636 float x = ToCallTime(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700637 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
638 // Here we convert it to dBov.
639 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200640 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700641 }
642 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200643 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700644 }
645
646 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
ivocbf676632016-11-24 08:30:34 -0800647 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin,
ivocaac9d6f2016-09-22 07:01:47 -0700648 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200649 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700650}
651
terelius54ce6802016-07-13 06:44:41 -0700652// For each SSRC, plot the time between the consecutive playouts.
653void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200654 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
655 // Filter on SSRC.
656 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700657 continue;
terelius54ce6802016-07-13 06:44:41 -0700658 }
terelius54ce6802016-07-13 06:44:41 -0700659
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200660 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
661 LineStyle::kBar);
662 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
663 const LoggedRtpPacketIncoming& new_packet) {
664 int64_t diff =
665 WrappingDifference(new_packet.rtp.header.sequenceNumber,
666 old_packet.rtp.header.sequenceNumber, 1ul << 16);
667 return diff;
668 };
669 ProcessPairs<LoggedRtpPacketIncoming, float>(GetSequenceNumberDiff,
670 stream.incoming_packets,
671 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700672 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700673 }
674
tereliusdc35dcd2016-08-01 12:03:27 -0700675 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
676 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
677 kTopMargin);
678 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700679}
680
Stefan Holmer99f8e082016-09-09 13:37:50 +0200681void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200682 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
683 const std::vector<LoggedRtpPacketIncoming>& packets =
684 stream.incoming_packets;
685 // Filter on SSRC.
686 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200687 continue;
688 }
689
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200690 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
691 LineStyle::kLine, PointStyle::kHighlight);
692 // TODO(terelius): Should the window and step size be read from the class
693 // instead?
694 const int64_t kWindowUs = 1000000;
695 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100696 SeqNumUnwrapper<uint16_t> unwrapper_;
697 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800698 size_t window_index_begin = 0;
699 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200700 uint64_t highest_seq_number =
701 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
702 uint64_t highest_prior_seq_number =
703 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800704
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200705 for (int64_t t = begin_time_; t < end_time_ + kStep; t += kStep) {
706 while (window_index_end < packets.size() &&
707 packets[window_index_end].rtp.log_time_us() < t) {
708 uint64_t sequence_number = unwrapper_.Unwrap(
709 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800710 highest_seq_number = std::max(highest_seq_number, sequence_number);
711 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200712 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200713 while (window_index_begin < packets.size() &&
714 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
715 uint64_t sequence_number = prior_unwrapper_.Unwrap(
716 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800717 highest_prior_seq_number =
718 std::max(highest_prior_seq_number, sequence_number);
719 ++window_index_begin;
720 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800721 float x = ToCallTime(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200722 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800723 if (expected_packets > 0) {
724 int64_t received_packets = window_index_end - window_index_begin;
725 int64_t lost_packets = expected_packets - received_packets;
726 float y = static_cast<float>(lost_packets) / expected_packets * 100;
727 time_series.points.emplace_back(x, y);
728 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200729 }
philipel35ba9bd2017-04-19 05:58:51 -0700730 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200731 }
732
733 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
734 plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
735 kTopMargin);
736 plot->SetTitle("Estimated incoming loss rate");
737}
738
terelius2ee076d2017-08-15 02:04:02 -0700739void EventLogAnalyzer::CreateIncomingDelayDeltaGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200740 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(kIncomingPacket)) {
741 // Filter on SSRC.
742 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
743 IsAudioSsrc(kIncomingPacket, stream.ssrc) ||
744 !IsVideoSsrc(kIncomingPacket, stream.ssrc) ||
745 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700746 continue;
747 }
terelius54ce6802016-07-13 06:44:41 -0700748
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200749 TimeSeries capture_time_data(
750 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
751 LineStyle::kBar);
terelius53dc23c2017-03-13 05:24:05 -0700752 ProcessPairs<LoggedRtpPacket, double>(NetworkDelayDiff_CaptureTime,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200753 stream.packet_view, begin_time_,
terelius53dc23c2017-03-13 05:24:05 -0700754 &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700755 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700756
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200757 TimeSeries send_time_data(
758 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
759 LineStyle::kBar);
terelius53dc23c2017-03-13 05:24:05 -0700760 ProcessPairs<LoggedRtpPacket, double>(NetworkDelayDiff_AbsSendTime,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200761 stream.packet_view, begin_time_,
terelius53dc23c2017-03-13 05:24:05 -0700762 &send_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700763 plot->AppendTimeSeries(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700764 }
765
tereliusdc35dcd2016-08-01 12:03:27 -0700766 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
767 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
768 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700769 plot->SetTitle("Network latency difference between consecutive packets");
terelius54ce6802016-07-13 06:44:41 -0700770}
771
terelius2ee076d2017-08-15 02:04:02 -0700772void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200773 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(kIncomingPacket)) {
774 // Filter on SSRC.
775 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
776 IsAudioSsrc(kIncomingPacket, stream.ssrc) ||
777 !IsVideoSsrc(kIncomingPacket, stream.ssrc) ||
778 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700779 continue;
780 }
terelius54ce6802016-07-13 06:44:41 -0700781
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200782 TimeSeries capture_time_data(
783 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
784 LineStyle::kLine);
terelius53dc23c2017-03-13 05:24:05 -0700785 AccumulatePairs<LoggedRtpPacket, double>(NetworkDelayDiff_CaptureTime,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200786 stream.packet_view, begin_time_,
terelius53dc23c2017-03-13 05:24:05 -0700787 &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700788 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700789
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200790 TimeSeries send_time_data(
791 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
792 LineStyle::kLine);
terelius53dc23c2017-03-13 05:24:05 -0700793 AccumulatePairs<LoggedRtpPacket, double>(NetworkDelayDiff_AbsSendTime,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200794 stream.packet_view, begin_time_,
terelius53dc23c2017-03-13 05:24:05 -0700795 &send_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700796 plot->AppendTimeSeries(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700797 }
798
tereliusdc35dcd2016-08-01 12:03:27 -0700799 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
800 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
801 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700802 plot->SetTitle("Network latency (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700803}
804
tereliusf736d232016-08-04 10:00:11 -0700805// Plot the fraction of packets lost (as perceived by the loss-based BWE).
806void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100807 TimeSeries time_series("Fraction lost", LineStyle::kLine,
808 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200809 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
810 float x = ToCallTime(bwe_update.log_time_us());
811 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700812 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700813 }
tereliusf736d232016-08-04 10:00:11 -0700814
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200815 plot->AppendTimeSeries(std::move(time_series));
tereliusf736d232016-08-04 10:00:11 -0700816 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
817 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
818 kTopMargin);
819 plot->SetTitle("Reported packet loss");
820}
821
terelius54ce6802016-07-13 06:44:41 -0700822// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200823void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
824 // TODO(terelius): This could be provided by the parser.
825 std::multimap<int64_t, size_t> packets_in_order;
826 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
827 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
828 packets_in_order.insert(
829 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700830 }
831
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200832 auto window_begin = packets_in_order.begin();
833 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700834 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700835
836 // Calculate a moving average of the bitrate and store in a TimeSeries.
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100837 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200838 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
839 while (window_end != packets_in_order.end() && window_end->first < time) {
840 bytes_in_window += window_end->second;
841 ++window_end;
terelius54ce6802016-07-13 06:44:41 -0700842 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200843 while (window_begin != packets_in_order.end() &&
844 window_begin->first < time - window_duration_) {
845 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
846 bytes_in_window -= window_begin->second;
847 ++window_begin;
848 }
849 float window_duration_in_seconds =
850 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
851 float x = ToCallTime(time);
852 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
853 bitrate_series.points.emplace_back(x, y);
854 }
855 plot->AppendTimeSeries(std::move(bitrate_series));
856
857 // Overlay the outgoing REMB over incoming bitrate.
858 TimeSeries remb_series("Remb", LineStyle::kStep);
859 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
860 float x = ToCallTime(rtcp.log_time_us());
861 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
862 remb_series.points.emplace_back(x, y);
863 }
864 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
865
866 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
867 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
868 plot->SetTitle("Incoming RTP bitrate");
869}
870
871// Plot the total bandwidth used by all RTP streams.
872void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
873 bool show_detector_state,
874 bool show_alr_state) {
875 // TODO(terelius): This could be provided by the parser.
876 std::multimap<int64_t, size_t> packets_in_order;
877 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
878 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
879 packets_in_order.insert(
880 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
881 }
882
883 auto window_begin = packets_in_order.begin();
884 auto window_end = packets_in_order.begin();
885 size_t bytes_in_window = 0;
886
887 // Calculate a moving average of the bitrate and store in a TimeSeries.
888 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
889 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
890 while (window_end != packets_in_order.end() && window_end->first < time) {
891 bytes_in_window += window_end->second;
892 ++window_end;
893 }
894 while (window_begin != packets_in_order.end() &&
895 window_begin->first < time - window_duration_) {
896 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
897 bytes_in_window -= window_begin->second;
898 ++window_begin;
terelius54ce6802016-07-13 06:44:41 -0700899 }
900 float window_duration_in_seconds =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800901 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
902 float x = ToCallTime(time);
terelius54ce6802016-07-13 06:44:41 -0700903 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
philipel35ba9bd2017-04-19 05:58:51 -0700904 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700905 }
philipel35ba9bd2017-04-19 05:58:51 -0700906 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700907
terelius8058e582016-07-25 01:32:41 -0700908 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200909 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
910 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
911 float x = ToCallTime(loss_update.log_time_us());
912 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
913 loss_series.points.emplace_back(x, y);
914 }
philipel10fc0e62017-04-11 01:50:23 -0700915
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200916 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
917 IntervalSeries overusing_series("Overusing", "#ff8e82",
918 IntervalSeries::kHorizontal);
919 IntervalSeries underusing_series("Underusing", "#5092fc",
920 IntervalSeries::kHorizontal);
921 IntervalSeries normal_series("Normal", "#c4ffc4",
922 IntervalSeries::kHorizontal);
923 IntervalSeries* last_series = &normal_series;
924 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700925
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200926 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700927
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200928 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
929 float x = ToCallTime(delay_update.log_time_us());
930 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700931
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200932 if (last_detector_state != delay_update.detector_state) {
933 last_series->intervals.emplace_back(last_detector_switch, x);
934 last_detector_state = delay_update.detector_state;
935 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700936
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200937 switch (delay_update.detector_state) {
938 case BandwidthUsage::kBwNormal:
939 last_series = &normal_series;
940 break;
941 case BandwidthUsage::kBwUnderusing:
942 last_series = &underusing_series;
943 break;
944 case BandwidthUsage::kBwOverusing:
945 last_series = &overusing_series;
946 break;
947 case BandwidthUsage::kLast:
948 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200949 }
950 }
philipel23c7f252017-07-14 06:30:03 -0700951
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200952 delay_series.points.emplace_back(x, y);
953 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200954
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200955 RTC_CHECK(last_series);
956 last_series->intervals.emplace_back(last_detector_switch, end_time_);
957
958 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
959 PointStyle::kHighlight);
960 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
961 float x = ToCallTime(cluster.log_time_us());
962 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
963 created_series.points.emplace_back(x, y);
964 }
965
966 TimeSeries result_series("Probing results.", LineStyle::kNone,
967 PointStyle::kHighlight);
968 for (auto& result : parsed_log_.bwe_probe_result_events()) {
969 if (result.bitrate_bps) {
970 float x = ToCallTime(result.log_time_us());
971 float y = static_cast<float>(*result.bitrate_bps) / 1000;
972 result_series.points.emplace_back(x, y);
973 }
974 }
975
976 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
977 bool previously_in_alr = false;
978 int64_t alr_start = 0;
979 for (auto& alr : parsed_log_.alr_state_events()) {
980 float y = ToCallTime(alr.log_time_us());
981 if (!previously_in_alr && alr.in_alr) {
982 alr_start = alr.log_time_us();
983 previously_in_alr = true;
984 } else if (previously_in_alr && !alr.in_alr) {
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100985 float x = ToCallTime(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100986 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200987 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +0000988 }
Björn Tereliusff612732018-04-25 14:23:01 +0000989 }
990
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200991 if (previously_in_alr) {
992 float x = ToCallTime(alr_start);
993 float y = ToCallTime(end_time_);
994 alr_state.intervals.emplace_back(x, y);
995 }
996
997 if (show_detector_state) {
998 plot->AppendIntervalSeries(std::move(overusing_series));
999 plot->AppendIntervalSeries(std::move(underusing_series));
1000 plot->AppendIntervalSeries(std::move(normal_series));
1001 }
1002
1003 if (show_alr_state) {
1004 plot->AppendIntervalSeries(std::move(alr_state));
1005 }
1006 plot->AppendTimeSeries(std::move(loss_series));
1007 plot->AppendTimeSeries(std::move(delay_series));
1008 plot->AppendTimeSeries(std::move(created_series));
1009 plot->AppendTimeSeries(std::move(result_series));
1010
1011 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001012 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001013 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
1014 float x = ToCallTime(rtcp.log_time_us());
1015 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001016 remb_series.points.emplace_back(x, y);
1017 }
1018 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1019
tereliusdc35dcd2016-08-01 12:03:27 -07001020 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1021 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001022 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001023}
1024
1025// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001026void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1027 Plot* plot) {
1028 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1029 // Filter on SSRC.
1030 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001031 continue;
terelius54ce6802016-07-13 06:44:41 -07001032 }
1033
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001034 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1035 LineStyle::kLine);
1036 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1037 return packet.total_length * 8.0 / 1000.0;
1038 };
terelius53dc23c2017-03-13 05:24:05 -07001039 MovingAverage<LoggedRtpPacket, double>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001040 GetPacketSizeKilobits, stream.packet_view, begin_time_, end_time_,
1041 window_duration_, step_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001042 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001043 }
1044
tereliusdc35dcd2016-08-01 12:03:27 -07001045 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1046 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001047 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001048}
1049
Bjorn Terelius28db2662017-10-04 14:22:43 +02001050void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001051 using RtpPacketType = LoggedRtpPacketOutgoing;
1052 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001053
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001054 // TODO(terelius): This could be provided by the parser.
1055 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1056 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1057 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1058 outgoing_rtp.insert(
1059 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001060 }
1061
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001062 const std::vector<TransportFeedbackType>& incoming_rtcp =
1063 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001064
1065 SimulatedClock clock(0);
1066 BitrateObserver observer;
1067 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001068 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001069 PacedSender pacer(&clock, &packet_router, &null_event_log);
1070 SendSideCongestionController cc(&clock, &observer, &null_event_log, &pacer);
Stefan Holmer13181032016-07-29 14:48:54 +02001071 // TODO(holmer): Log the call config and use that here instead.
1072 static const uint32_t kDefaultStartBitrateBps = 300000;
1073 cc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1074
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001075 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1076 PointStyle::kHighlight);
1077 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1078 PointStyle::kHighlight);
1079 TimeSeries acked_estimate_time_series(
1080 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001081
1082 auto rtp_iterator = outgoing_rtp.begin();
1083 auto rtcp_iterator = incoming_rtcp.begin();
1084
1085 auto NextRtpTime = [&]() {
1086 if (rtp_iterator != outgoing_rtp.end())
1087 return static_cast<int64_t>(rtp_iterator->first);
1088 return std::numeric_limits<int64_t>::max();
1089 };
1090
1091 auto NextRtcpTime = [&]() {
1092 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001093 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001094 return std::numeric_limits<int64_t>::max();
1095 };
1096
1097 auto NextProcessTime = [&]() {
1098 if (rtcp_iterator != incoming_rtcp.end() ||
1099 rtp_iterator != outgoing_rtp.end()) {
1100 return clock.TimeInMicroseconds() +
1101 std::max<int64_t>(cc.TimeUntilNextProcess() * 1000, 0);
1102 }
1103 return std::numeric_limits<int64_t>::max();
1104 };
1105
Stefan Holmer492ee282016-10-27 17:19:20 +02001106 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001107#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1108 // The event_log_visualizer should normally not be compiled with
1109 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1110 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1111 // and piping the output to plot_dynamics.py can be used as a hack to get the
1112 // internal state of various BWE components. In this case, it is important
1113 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1114 // SendSideCongestionController since that would lead to duplicate outputs.
1115 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
1116 rtc::MakeUnique<BitrateEstimator>());
1117#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001118 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
Stefan Holmer492ee282016-10-27 17:19:20 +02001119 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001120 while (time_us != std::numeric_limits<int64_t>::max()) {
1121 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1122 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001123 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001124 cc.OnTransportFeedback(rtcp_iterator->transport_feedback);
1125 std::vector<PacketFeedback> feedback = cc.GetTransportFeedbackVector();
1126 SortPacketFeedbackVector(&feedback);
1127 rtc::Optional<uint32_t> bitrate_bps;
1128 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001129#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001130 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001131#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001132 for (const PacketFeedback& packet : feedback)
1133 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1134 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
Stefan Holmer13181032016-07-29 14:48:54 +02001135 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001136 float x = ToCallTime(clock.TimeInMicroseconds());
1137 float y = bitrate_bps.value_or(0) / 1000;
1138 acked_time_series.points.emplace_back(x, y);
1139#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1140 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1141 acked_estimate_time_series.points.emplace_back(x, y);
1142#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001143 ++rtcp_iterator;
1144 }
1145 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001146 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001147 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1148 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1149 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
1150 cc.AddPacket(rtp_packet.rtp.header.ssrc,
1151 rtp_packet.rtp.header.extension.transportSequenceNumber,
1152 rtp_packet.rtp.total_length, PacedPacketInfo());
Stefan Holmer13181032016-07-29 14:48:54 +02001153 rtc::SentPacket sent_packet(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001154 rtp_packet.rtp.header.extension.transportSequenceNumber,
1155 rtp_packet.rtp.log_time_us() / 1000);
Stefan Holmer13181032016-07-29 14:48:54 +02001156 cc.OnSentPacket(sent_packet);
1157 }
1158 ++rtp_iterator;
1159 }
stefanc3de0332016-08-02 07:22:17 -07001160 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1161 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Stefan Holmer13181032016-07-29 14:48:54 +02001162 cc.Process();
stefanc3de0332016-08-02 07:22:17 -07001163 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001164 if (observer.GetAndResetBitrateUpdated() ||
1165 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001166 uint32_t y = observer.last_bitrate_bps() / 1000;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001167 float x = ToCallTime(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001168 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001169 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001170 }
1171 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1172 }
1173 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001174 plot->AppendTimeSeries(std::move(time_series));
1175 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001176 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001177
tereliusdc35dcd2016-08-01 12:03:27 -07001178 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1179 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001180 plot->SetTitle("Simulated send-side BWE behavior");
1181}
1182
1183void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001184 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001185 class RembInterceptingPacketRouter : public PacketRouter {
1186 public:
1187 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1188 uint32_t bitrate_bps) override {
1189 last_bitrate_bps_ = bitrate_bps;
1190 bitrate_updated_ = true;
1191 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1192 }
1193 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1194 bool GetAndResetBitrateUpdated() {
1195 bool bitrate_updated = bitrate_updated_;
1196 bitrate_updated_ = false;
1197 return bitrate_updated;
1198 }
1199
1200 private:
1201 uint32_t last_bitrate_bps_;
1202 bool bitrate_updated_;
1203 };
1204
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001205 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001206
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001207 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1208 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1209 for (const auto& rtp_packet : stream.incoming_packets)
1210 incoming_rtp.insert(
1211 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001212 }
1213 }
1214
1215 SimulatedClock clock(0);
1216 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001217 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001218 // Is this intentional?
1219 ReceiveSideCongestionController rscc(&clock, &packet_router);
1220 // TODO(holmer): Log the call config and use that here instead.
1221 // static const uint32_t kDefaultStartBitrateBps = 300000;
1222 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1223
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001224 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1225 PointStyle::kHighlight);
1226 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001227
1228 RateStatistics acked_bitrate(250, 8000);
1229 int64_t last_update_us = 0;
1230 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001231 const RtpPacketType& packet = *kv.second;
1232 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1233 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1234 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001235 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001236 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001237 acked_bitrate.Update(payload, arrival_time_ms);
1238 rtc::Optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
1239 if (bitrate_bps) {
1240 uint32_t y = *bitrate_bps / 1000;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001241 float x = ToCallTime(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001242 acked_time_series.points.emplace_back(x, y);
1243 }
1244 if (packet_router.GetAndResetBitrateUpdated() ||
1245 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1246 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001247 float x = ToCallTime(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001248 time_series.points.emplace_back(x, y);
1249 last_update_us = clock.TimeInMicroseconds();
1250 }
1251 }
1252 // Add the data set to the plot.
1253 plot->AppendTimeSeries(std::move(time_series));
1254 plot->AppendTimeSeries(std::move(acked_time_series));
1255
1256 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1257 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1258 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001259}
1260
tereliuse34c19c2016-08-15 08:47:14 -07001261void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001262 using RtpPacketType = LoggedRtpPacketOutgoing;
1263 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
stefanc3de0332016-08-02 07:22:17 -07001264
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001265 // TODO(terelius): This could be provided by the parser.
1266 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1267 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1268 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1269 outgoing_rtp.insert(
1270 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
stefanc3de0332016-08-02 07:22:17 -07001271 }
1272
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001273 const std::vector<TransportFeedbackType>& incoming_rtcp =
1274 parsed_log_.transport_feedbacks(kIncomingPacket);
stefanc3de0332016-08-02 07:22:17 -07001275
1276 SimulatedClock clock(0);
elad.alon5bbf43f2017-03-09 06:40:08 -08001277 TransportFeedbackAdapter feedback_adapter(&clock);
stefanc3de0332016-08-02 07:22:17 -07001278
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001279 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1280 PointStyle::kHighlight);
1281 TimeSeries time_series("Network Delay Change", LineStyle::kLine,
1282 PointStyle::kHighlight);
stefanc3de0332016-08-02 07:22:17 -07001283 int64_t estimated_base_delay_ms = std::numeric_limits<int64_t>::max();
1284
1285 auto rtp_iterator = outgoing_rtp.begin();
1286 auto rtcp_iterator = incoming_rtcp.begin();
1287
1288 auto NextRtpTime = [&]() {
1289 if (rtp_iterator != outgoing_rtp.end())
1290 return static_cast<int64_t>(rtp_iterator->first);
1291 return std::numeric_limits<int64_t>::max();
1292 };
1293
1294 auto NextRtcpTime = [&]() {
1295 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001296 return static_cast<int64_t>(rtcp_iterator->log_time_us());
stefanc3de0332016-08-02 07:22:17 -07001297 return std::numeric_limits<int64_t>::max();
1298 };
1299
1300 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
stefana0a8ed72017-09-06 02:06:32 -07001301 int64_t prev_y = 0;
stefanc3de0332016-08-02 07:22:17 -07001302 while (time_us != std::numeric_limits<int64_t>::max()) {
1303 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1304 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
1305 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001306 feedback_adapter.OnTransportFeedback(rtcp_iterator->transport_feedback);
1307 std::vector<PacketFeedback> feedback =
1308 feedback_adapter.GetTransportFeedbackVector();
1309 SortPacketFeedbackVector(&feedback);
1310 for (const PacketFeedback& packet : feedback) {
1311 float x = ToCallTime(clock.TimeInMicroseconds());
1312 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1313 late_feedback_series.points.emplace_back(x, prev_y);
1314 continue;
stefanc3de0332016-08-02 07:22:17 -07001315 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001316 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1317 prev_y = y;
1318 estimated_base_delay_ms = std::min(y, estimated_base_delay_ms);
1319 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001320 }
1321 ++rtcp_iterator;
1322 }
1323 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1324 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001325 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1326 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1327 feedback_adapter.AddPacket(
1328 rtp_packet.rtp.header.ssrc,
1329 rtp_packet.rtp.header.extension.transportSequenceNumber,
1330 rtp_packet.rtp.total_length, PacedPacketInfo());
stefanc3de0332016-08-02 07:22:17 -07001331 feedback_adapter.OnSentPacket(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001332 rtp_packet.rtp.header.extension.transportSequenceNumber,
1333 rtp_packet.rtp.log_time_us() / 1000);
stefanc3de0332016-08-02 07:22:17 -07001334 }
1335 ++rtp_iterator;
1336 }
1337 time_us = std::min(NextRtpTime(), NextRtcpTime());
1338 }
1339 // We assume that the base network delay (w/o queues) is the min delay
1340 // observed during the call.
1341 for (TimeSeriesPoint& point : time_series.points)
1342 point.y -= estimated_base_delay_ms;
stefana0a8ed72017-09-06 02:06:32 -07001343 for (TimeSeriesPoint& point : late_feedback_series.points)
1344 point.y -= estimated_base_delay_ms;
stefanc3de0332016-08-02 07:22:17 -07001345 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001346 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1347 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001348
1349 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1350 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
1351 plot->SetTitle("Network Delay Change.");
1352}
stefan08383272016-12-20 08:51:52 -08001353
Bjorn Terelius0295a962017-10-25 17:42:41 +02001354void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001355 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1356 const std::vector<LoggedRtpPacketOutgoing>& packets =
1357 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001358
1359 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001360 RTC_LOG(LS_WARNING)
1361 << "Can't estimate a the RTP clock frequency or the "
1362 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001363 continue;
1364 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001365 int64_t end_time_us = log_segments_.empty()
1366 ? std::numeric_limits<int64_t>::max()
1367 : log_segments_.front().second;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001368 rtc::Optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001369 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001370 if (!estimated_frequency)
1371 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001372 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1373 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001374 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001375 << "Video stream should use a 90 kHz clock but appears to use "
1376 << *estimated_frequency / 1000 << ". Discarding.";
1377 continue;
1378 }
1379
1380 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001381 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001382 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001383 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001384 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1385 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001386 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1387 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1388 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001389 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001390 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001391 first_capture_timestamp) /
1392 *estimated_frequency * 1000;
1393 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001394 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1395 1000;
1396 float x = ToCallTime(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001397 float y = send_time_ms - capture_time_ms;
1398 pacer_delay_series.points.emplace_back(x, y);
1399 }
1400 plot->AppendTimeSeries(std::move(pacer_delay_series));
1401 }
1402
1403 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1404 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1405 plot->SetTitle(
1406 "Delay from capture to send time. (First packet normalized to 0.)");
1407}
1408
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001409void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1410 Plot* plot) {
1411 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1412 TimeSeries rtp_timestamps(
1413 GetStreamName(direction, stream.ssrc) + " capture-time",
1414 LineStyle::kLine, PointStyle::kHighlight);
1415 for (const auto& packet : stream.packet_view) {
1416 float x = ToCallTime(packet.log_time_us());
1417 float y = packet.header.timestamp;
1418 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001419 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001420 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001421
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001422 TimeSeries rtcp_timestamps(
1423 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1424 LineStyle::kLine, PointStyle::kHighlight);
1425 // TODO(terelius): Why only sender reports?
1426 const auto& sender_reports = parsed_log_.sender_reports(direction);
1427 for (const auto& rtcp : sender_reports) {
1428 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1429 continue;
1430 float x = ToCallTime(rtcp.log_time_us());
1431 float y = rtcp.sr.rtp_timestamp();
1432 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001433 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001434 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001435 }
1436
1437 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001438 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1439 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001440}
michaelt6e5b2192017-02-22 07:33:27 -08001441
1442void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001443 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1444 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001445 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
1446 -> rtc::Optional<float> {
1447 if (ana_event.config.bitrate_bps)
1448 return rtc::Optional<float>(
1449 static_cast<float>(*ana_event.config.bitrate_bps));
1450 return rtc::nullopt;
1451 };
1452 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
1453 GetAnaBitrateBps, parsed_log_.audio_network_adaptation_events(),
1454 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001455 plot->AppendTimeSeries(std::move(time_series));
michaelt6e5b2192017-02-22 07:33:27 -08001456 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1457 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1458 plot->SetTitle("Reported audio encoder target bitrate");
1459}
1460
1461void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001462 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1463 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001464 auto GetAnaFrameLengthMs =
1465 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001466 if (ana_event.config.frame_length_ms)
1467 return rtc::Optional<float>(
1468 static_cast<float>(*ana_event.config.frame_length_ms));
1469 return rtc::Optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001470 };
1471 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
1472 GetAnaFrameLengthMs, parsed_log_.audio_network_adaptation_events(),
1473 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001474 plot->AppendTimeSeries(std::move(time_series));
michaelt6e5b2192017-02-22 07:33:27 -08001475 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1476 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1477 plot->SetTitle("Reported audio encoder frame length");
1478}
1479
terelius2ee076d2017-08-15 02:04:02 -07001480void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001481 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001482 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001483 auto GetAnaPacketLoss =
1484 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001485 if (ana_event.config.uplink_packet_loss_fraction)
1486 return rtc::Optional<float>(static_cast<float>(
1487 *ana_event.config.uplink_packet_loss_fraction));
1488 return rtc::Optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001489 };
1490 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
1491 GetAnaPacketLoss, parsed_log_.audio_network_adaptation_events(),
1492 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001493 plot->AppendTimeSeries(std::move(time_series));
michaelt6e5b2192017-02-22 07:33:27 -08001494 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1495 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1496 kTopMargin);
1497 plot->SetTitle("Reported audio encoder lost packets");
1498}
1499
1500void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001501 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1502 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001503 auto GetAnaFecEnabled =
1504 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001505 if (ana_event.config.enable_fec)
1506 return rtc::Optional<float>(
1507 static_cast<float>(*ana_event.config.enable_fec));
1508 return rtc::Optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001509 };
1510 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
1511 GetAnaFecEnabled, parsed_log_.audio_network_adaptation_events(),
1512 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001513 plot->AppendTimeSeries(std::move(time_series));
michaelt6e5b2192017-02-22 07:33:27 -08001514 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1515 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1516 plot->SetTitle("Reported audio encoder FEC");
1517}
1518
1519void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001520 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1521 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001522 auto GetAnaDtxEnabled =
1523 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001524 if (ana_event.config.enable_dtx)
1525 return rtc::Optional<float>(
1526 static_cast<float>(*ana_event.config.enable_dtx));
1527 return rtc::Optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001528 };
1529 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
1530 GetAnaDtxEnabled, parsed_log_.audio_network_adaptation_events(),
1531 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001532 plot->AppendTimeSeries(std::move(time_series));
michaelt6e5b2192017-02-22 07:33:27 -08001533 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1534 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1535 plot->SetTitle("Reported audio encoder DTX");
1536}
1537
1538void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001539 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1540 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001541 auto GetAnaNumChannels =
1542 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001543 if (ana_event.config.num_channels)
1544 return rtc::Optional<float>(
1545 static_cast<float>(*ana_event.config.num_channels));
1546 return rtc::Optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001547 };
1548 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
1549 GetAnaNumChannels, parsed_log_.audio_network_adaptation_events(),
1550 begin_time_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001551 plot->AppendTimeSeries(std::move(time_series));
michaelt6e5b2192017-02-22 07:33:27 -08001552 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1553 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1554 kBottomMargin, kTopMargin);
1555 plot->SetTitle("Reported audio encoder number of channels");
1556}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001557
1558class NetEqStreamInput : public test::NetEqInput {
1559 public:
1560 // Does not take any ownership, and all pointers must refer to valid objects
1561 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001562 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001563 const std::vector<LoggedAudioPlayoutEvent>* output_events,
1564 rtc::Optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001565 : packet_stream_(*packet_stream),
1566 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001567 output_events_it_(output_events->begin()),
1568 output_events_end_(output_events->end()),
1569 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001570 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001571 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001572 }
1573
1574 rtc::Optional<int64_t> NextPacketTime() const override {
1575 if (packet_stream_it_ == packet_stream_.end()) {
Oskar Sundbom3928dbc2017-11-16 10:53:09 +01001576 return rtc::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001577 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001578 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Oskar Sundbom3928dbc2017-11-16 10:53:09 +01001579 return rtc::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001580 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001581 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001582 }
1583
1584 rtc::Optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001585 if (output_events_it_ == output_events_end_) {
Oskar Sundbom3928dbc2017-11-16 10:53:09 +01001586 return rtc::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001587 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001588 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Oskar Sundbom3928dbc2017-11-16 10:53:09 +01001589 return rtc::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001590 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001591 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001592 }
1593
1594 std::unique_ptr<PacketData> PopPacket() override {
1595 if (packet_stream_it_ == packet_stream_.end()) {
1596 return std::unique_ptr<PacketData>();
1597 }
1598 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001599 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001600 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001601
1602 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1603 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001604 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1605 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001606 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1607
1608 ++packet_stream_it_;
1609 return packet_data;
1610 }
1611
1612 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001613 if (output_events_it_ != output_events_end_) {
1614 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001615 }
1616 }
1617
1618 bool ended() const override { return !NextEventTime(); }
1619
1620 rtc::Optional<RTPHeader> NextHeader() const override {
1621 if (packet_stream_it_ == packet_stream_.end()) {
Oskar Sundbom3928dbc2017-11-16 10:53:09 +01001622 return rtc::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001623 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001624 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001625 }
1626
1627 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001628 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1629 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001630 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1631 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
1632 const rtc::Optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001633};
1634
1635namespace {
1636// Creates a NetEq test object and all necessary input and output helpers. Runs
1637// the test and returns the NetEqDelayAnalyzer object that was used to
1638// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001639std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001640 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001641 const std::vector<LoggedAudioPlayoutEvent>* output_events,
1642 rtc::Optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001643 const std::string& replacement_file_name,
1644 int file_sample_rate_hz) {
1645 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001646 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001647
1648 constexpr int kReplacementPt = 127;
1649 std::set<uint8_t> cn_types;
1650 std::set<uint8_t> forbidden_types;
1651 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1652 cn_types, forbidden_types));
1653
1654 NetEq::Config config;
1655 config.max_packets_in_buffer = 200;
1656 config.enable_fast_accelerate = true;
1657
1658 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1659
1660 test::NetEqTest::DecoderMap codecs;
1661
1662 // Create a "replacement decoder" that produces the decoded audio by reading
1663 // from a file rather than from the encoded payloads.
1664 std::unique_ptr<test::ResampleInputAudioFile> replacement_file(
1665 new test::ResampleInputAudioFile(replacement_file_name,
1666 file_sample_rate_hz));
1667 replacement_file->set_output_rate_hz(48000);
1668 std::unique_ptr<AudioDecoder> replacement_decoder(
1669 new test::FakeDecodeFromFile(std::move(replacement_file), 48000, false));
1670 test::NetEqTest::ExtDecoderMap ext_codecs;
1671 ext_codecs[kReplacementPt] = {replacement_decoder.get(),
1672 NetEqDecoder::kDecoderArbitrary,
1673 "replacement codec"};
1674
1675 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1676 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001677 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1678 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001679 test::DefaultNetEqTestErrorCallback error_cb;
1680 test::NetEqTest::Callbacks callbacks;
1681 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001682 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1683 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001684
1685 test::NetEqTest test(config, codecs, ext_codecs, std::move(input),
1686 std::move(output), callbacks);
1687 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001688 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001689}
1690} // namespace
1691
Minyue Lic6ff7572018-05-04 09:46:44 +02001692EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001693 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001694 int file_sample_rate_hz) const {
1695 NetEqStatsGetterMap neteq_stats;
1696
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001697 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001698 const uint32_t ssrc = stream.ssrc;
1699 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1700 continue;
1701 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1702 &stream.incoming_packets;
1703 if (audio_packets == nullptr) {
1704 // No incoming audio stream found.
1705 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001706 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001707
Minyue Li27e2b7d2018-05-07 15:20:24 +02001708 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1709
1710 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1711 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1712 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1713 // Could not find output events with SSRC matching the input audio stream.
1714 // Using the first available stream of output events.
1715 output_events_it = parsed_log_.audio_playout_events().cbegin();
1716 }
1717
1718 rtc::Optional<int64_t> end_time_ms =
1719 log_segments_.empty()
1720 ? rtc::nullopt
1721 : rtc::Optional<int64_t>(log_segments_.front().second / 1000);
1722
1723 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1724 audio_packets, &output_events_it->second, end_time_ms,
1725 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001726 }
1727
Minyue Lic6ff7572018-05-04 09:46:44 +02001728 return neteq_stats;
1729}
1730
1731// Plots the jitter buffer delay profile. This will plot only for the first
1732// incoming audio SSRC. If the stream contains more than one incoming audio
1733// SSRC, all but the first will be ignored.
1734void EventLogAnalyzer::CreateAudioJitterBufferGraph(
1735 const NetEqStatsGetterMap& neteq_stats,
1736 Plot* plot) const {
1737 if (neteq_stats.size() < 1)
1738 return;
1739
1740 const uint32_t ssrc = neteq_stats.begin()->first;
1741
henrik.lundin3c938fc2017-06-14 06:09:58 -07001742 std::vector<float> send_times_s;
1743 std::vector<float> arrival_delay_ms;
1744 std::vector<float> corrected_arrival_delay_ms;
1745 std::vector<rtc::Optional<float>> playout_delay_ms;
1746 std::vector<rtc::Optional<float>> target_delay_ms;
Minyue Lic6ff7572018-05-04 09:46:44 +02001747 neteq_stats.at(ssrc)->delay_analyzer()->CreateGraphs(
1748 &send_times_s, &arrival_delay_ms, &corrected_arrival_delay_ms,
1749 &playout_delay_ms, &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001750 RTC_DCHECK_EQ(send_times_s.size(), arrival_delay_ms.size());
1751 RTC_DCHECK_EQ(send_times_s.size(), corrected_arrival_delay_ms.size());
1752 RTC_DCHECK_EQ(send_times_s.size(), playout_delay_ms.size());
1753 RTC_DCHECK_EQ(send_times_s.size(), target_delay_ms.size());
1754
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001755 std::map<uint32_t, TimeSeries> time_series_packet_arrival;
1756 std::map<uint32_t, TimeSeries> time_series_relative_packet_arrival;
1757 std::map<uint32_t, TimeSeries> time_series_play_time;
1758 std::map<uint32_t, TimeSeries> time_series_target_time;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001759 float min_y_axis = 0.f;
1760 float max_y_axis = 0.f;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001761 for (size_t i = 0; i < send_times_s.size(); ++i) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001762 time_series_packet_arrival[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001763 TimeSeriesPoint(send_times_s[i], arrival_delay_ms[i]));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001764 time_series_relative_packet_arrival[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001765 TimeSeriesPoint(send_times_s[i], corrected_arrival_delay_ms[i]));
1766 min_y_axis = std::min(min_y_axis, corrected_arrival_delay_ms[i]);
1767 max_y_axis = std::max(max_y_axis, corrected_arrival_delay_ms[i]);
1768 if (playout_delay_ms[i]) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001769 time_series_play_time[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001770 TimeSeriesPoint(send_times_s[i], *playout_delay_ms[i]));
1771 min_y_axis = std::min(min_y_axis, *playout_delay_ms[i]);
1772 max_y_axis = std::max(max_y_axis, *playout_delay_ms[i]);
1773 }
1774 if (target_delay_ms[i]) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001775 time_series_target_time[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001776 TimeSeriesPoint(send_times_s[i], *target_delay_ms[i]));
1777 min_y_axis = std::min(min_y_axis, *target_delay_ms[i]);
1778 max_y_axis = std::max(max_y_axis, *target_delay_ms[i]);
1779 }
1780 }
1781
1782 // This code is adapted for a single stream. The creation of the streams above
1783 // guarantee that no more than one steam is included. If multiple streams are
1784 // to be plotted, they should likely be given distinct labels below.
1785 RTC_DCHECK_EQ(time_series_relative_packet_arrival.size(), 1);
1786 for (auto& series : time_series_relative_packet_arrival) {
1787 series.second.label = "Relative packet arrival delay";
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001788 series.second.line_style = LineStyle::kLine;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001789 plot->AppendTimeSeries(std::move(series.second));
1790 }
1791 RTC_DCHECK_EQ(time_series_play_time.size(), 1);
1792 for (auto& series : time_series_play_time) {
1793 series.second.label = "Playout delay";
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001794 series.second.line_style = LineStyle::kLine;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001795 plot->AppendTimeSeries(std::move(series.second));
1796 }
1797 RTC_DCHECK_EQ(time_series_target_time.size(), 1);
1798 for (auto& series : time_series_target_time) {
1799 series.second.label = "Target delay";
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001800 series.second.line_style = LineStyle::kLine;
1801 series.second.point_style = PointStyle::kHighlight;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001802 plot->AppendTimeSeries(std::move(series.second));
1803 }
1804
1805 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1806 plot->SetYAxis(min_y_axis, max_y_axis, "Relative delay (ms)", kBottomMargin,
1807 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001808 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
1809}
1810
1811void EventLogAnalyzer::CreateNetEqStatsGraph(
1812 const NetEqStatsGetterMap& neteq_stats,
1813 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
1814 const std::string& plot_name,
1815 Plot* plot) const {
1816 if (neteq_stats.size() < 1)
1817 return;
1818
1819 std::map<uint32_t, TimeSeries> time_series;
1820 float min_y_axis = std::numeric_limits<float>::max();
1821 float max_y_axis = std::numeric_limits<float>::min();
1822
1823 for (const auto& st : neteq_stats) {
1824 const uint32_t ssrc = st.first;
1825 const auto& stats = st.second->stats();
1826
1827 for (size_t i = 0; i < stats.size(); ++i) {
1828 const float time = ToCallTime(stats[i].first * 1000); // ms to us.
1829 const float value = stats_extractor(stats[i].second);
1830 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
1831 min_y_axis = std::min(min_y_axis, value);
1832 max_y_axis = std::max(max_y_axis, value);
1833 }
1834 }
1835
1836 for (auto& series : time_series) {
1837 series.second.label = GetStreamName(kIncomingPacket, series.first);
1838 series.second.line_style = LineStyle::kLine;
1839 plot->AppendTimeSeries(std::move(series.second));
1840 }
1841
1842 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1843 plot->SetYAxis(min_y_axis, max_y_axis, plot_name, kBottomMargin, kTopMargin);
1844 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001845}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001846
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001847void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1848 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001849 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001850 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1851 configs_by_cp_id.end()) {
1852 const std::string candidate_pair_desc =
1853 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001854 configs_by_cp_id[config.candidate_pair_id] =
1855 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1856 candidate_pair_desc,
1857 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001858 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1859 candidate_pair_desc;
1860 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001861 float x = ToCallTime(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001862 float y = static_cast<float>(config.type);
1863 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1864 }
1865
1866 // TODO(qingsi): There can be a large number of candidate pairs generated by
1867 // certain calls and the frontend cannot render the chart in this case due to
1868 // the failure of generating a palette with the same number of colors.
1869 for (auto& kv : configs_by_cp_id) {
1870 plot->AppendTimeSeries(std::move(kv.second));
1871 }
1872
1873 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1874 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
1875 kTopMargin);
1876 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1877}
1878
1879std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1880 uint32_t candidate_pair_id) {
1881 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1882 candidate_pair_desc_by_id_.end()) {
1883 return candidate_pair_desc_by_id_[candidate_pair_id];
1884 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001885 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001886 // TODO(qingsi): Add the handling of the "Updated" config event after the
1887 // visualization of property change for candidate pairs is introduced.
1888 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1889 candidate_pair_desc_by_id_.end()) {
1890 const std::string candidate_pair_desc =
1891 GetCandidatePairLogDescriptionAsString(config);
1892 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1893 candidate_pair_desc;
1894 }
1895 }
1896 return candidate_pair_desc_by_id_[candidate_pair_id];
1897}
1898
1899void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1900 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001901 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001902 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1903 checks_by_cp_id.end()) {
1904 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08001905 "[" + std::to_string(event.candidate_pair_id) + "]" +
1906 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001907 LineStyle::kNone, PointStyle::kHighlight);
1908 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001909 float x = ToCallTime(event.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001910 float y = static_cast<float>(event.type);
1911 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1912 }
1913
1914 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1915 for (auto& kv : checks_by_cp_id) {
1916 plot->AppendTimeSeries(std::move(kv.second));
1917 }
1918
1919 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
1920 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
1921 kTopMargin);
1922 plot->SetTitle("[IceEventLog] ICE connectivity checks");
1923}
1924
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001925void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001926 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001927 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
1928 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1929 }
1930 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
1931 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1932 }
1933 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
1934 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1935 }
1936 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
1937 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1938 }
1939 for (const auto& alert : incoming_seq_num_jumps_) {
1940 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1941 }
1942 for (const auto& alert : incoming_capture_time_jumps_) {
1943 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1944 }
1945 for (const auto& alert : outgoing_seq_num_jumps_) {
1946 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1947 }
1948 for (const auto& alert : outgoing_capture_time_jumps_) {
1949 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1950 }
1951 for (const auto& alert : outgoing_high_loss_alerts_) {
1952 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001953 }
1954 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
1955}
1956
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001957void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
1958 // With 100 packets/s (~800kbps), false positives would require 10 s without
1959 // data.
1960 constexpr int64_t kMaxSeqNumJump = 1000;
1961 // With a 90 kHz clock, false positives would require 10 s without data.
1962 constexpr int64_t kMaxCaptureTimeJump = 900000;
1963
1964 int64_t end_time_us = log_segments_.empty()
1965 ? std::numeric_limits<int64_t>::max()
1966 : log_segments_.front().second;
1967
1968 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
1969 rtc::Optional<int64_t> last_seq_num;
1970 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
1971 rtc::Optional<int64_t> last_capture_time;
1972 // Check for gaps in sequence numbers and capture timestamps.
1973 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1974 for (const auto& packet : stream.packet_view) {
1975 if (packet.log_time_us() > end_time_us) {
1976 // Only process the first (LOG_START, LOG_END) segment.
1977 break;
1978 }
1979
1980 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
1981 if (last_seq_num.has_value() &&
1982 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
1983 Alert_SeqNumJump(direction, ToCallTime(packet.log_time_us()),
1984 packet.header.ssrc);
1985 }
1986 last_seq_num.emplace(seq_num);
1987
1988 int64_t capture_time =
1989 capture_time_unwrapper.Unwrap(packet.header.timestamp);
1990 if (last_capture_time.has_value() &&
1991 std::abs(capture_time - last_capture_time.value()) >
1992 kMaxCaptureTimeJump) {
1993 Alert_CaptureTimeJump(direction, ToCallTime(packet.log_time_us()),
1994 packet.header.ssrc);
1995 }
1996 last_capture_time.emplace(capture_time);
1997 }
1998 }
1999}
2000
2001void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2002 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2003 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2004 int64_t end_time_us = log_segments_.empty()
2005 ? std::numeric_limits<int64_t>::max()
2006 : log_segments_.front().second;
2007
2008 // TODO(terelius): The parser could provide a list of all packets, ordered
2009 // by time, for each direction.
2010 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2011 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2012 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2013 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2014 }
2015 rtc::Optional<int64_t> last_rtp_time;
2016 for (const auto& kv : rtp_in_direction) {
2017 int64_t timestamp = kv.first;
2018 if (timestamp > end_time_us) {
2019 // Only process the first (LOG_START, LOG_END) segment.
2020 break;
2021 }
2022 int64_t duration = timestamp - last_rtp_time.value_or(0);
2023 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2024 // No packet sent/received for more than 500 ms.
2025 Alert_RtpLogTimeGap(direction, ToCallTime(timestamp), duration / 1000);
2026 }
2027 last_rtp_time.emplace(timestamp);
2028 }
2029
2030 rtc::Optional<int64_t> last_rtcp_time;
2031 if (direction == kIncomingPacket) {
2032 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2033 if (rtcp.log_time_us() > end_time_us) {
2034 // Only process the first (LOG_START, LOG_END) segment.
2035 break;
2036 }
2037 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2038 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2039 // No feedback sent/received for more than 2000 ms.
2040 Alert_RtcpLogTimeGap(direction, ToCallTime(rtcp.log_time_us()),
2041 duration / 1000);
2042 }
2043 last_rtcp_time.emplace(rtcp.log_time_us());
2044 }
2045 } else {
2046 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2047 if (rtcp.log_time_us() > end_time_us) {
2048 // Only process the first (LOG_START, LOG_END) segment.
2049 break;
2050 }
2051 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2052 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2053 // No feedback sent/received for more than 2000 ms.
2054 Alert_RtcpLogTimeGap(direction, ToCallTime(rtcp.log_time_us()),
2055 duration / 1000);
2056 }
2057 last_rtcp_time.emplace(rtcp.log_time_us());
2058 }
2059 }
2060}
2061
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002062// TODO(terelius): Notifications could possibly be generated by the same code
2063// that produces the graphs. There is some code duplication that could be
2064// avoided, but that might be solved anyway when we move functionality from the
2065// analyzer to the parser.
2066void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002067 CreateStreamGapAlerts(kIncomingPacket);
2068 CreateStreamGapAlerts(kOutgoingPacket);
2069 CreateTransmissionGapAlerts(kIncomingPacket);
2070 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002071
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002072 int64_t end_time_us = log_segments_.empty()
2073 ? std::numeric_limits<int64_t>::max()
2074 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002075
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002076 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002077 // Loss feedback
2078 int64_t total_lost_packets = 0;
2079 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002080 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2081 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002082 // Only process the first (LOG_START, LOG_END) segment.
2083 break;
2084 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002085 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002086 bwe_update.expected_packets;
2087 total_lost_packets += lost_packets;
2088 total_expected_packets += bwe_update.expected_packets;
2089 }
2090 double avg_outgoing_loss =
2091 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002092 if (avg_outgoing_loss > kMaxLossFraction) {
2093 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002094 }
2095}
2096
terelius54ce6802016-07-13 06:44:41 -07002097} // namespace webrtc