blob: f20d301d161b3b91ef2859dda74ad6fe947283a8 [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"
Sebastian Jansson439f0bc2018-02-20 10:46:39 +010034#include "modules/congestion_controller/delay_based_bwe.h"
Sebastian Jansson172fd852018-05-24 14:17:06 +020035#include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
36#include "modules/congestion_controller/goog_cc/bitrate_estimator.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>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200133absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200134 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)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200154 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200155 }
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.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200169 return absl::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
Danil Chapovalov431abd92018-06-18 12:54:17 +0200177absl::optional<double> NetworkDelayDiff_AbsSendTime(
terelius53dc23c2017-03-13 05:24:05 -0700178 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 {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200191 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700192 }
193}
194
Danil Chapovalov431abd92018-06-18 12:54:17 +0200195absl::optional<double> NetworkDelayDiff_CaptureTime(
terelius53dc23c2017-03-13 05:24:05 -0700196 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>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200232void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200233 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200234 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200235 TimeSeries* result) {
236 for (size_t i = 0; i < data_view.size(); i++) {
237 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200238 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200239 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700240 if (y)
241 result->points.emplace_back(x, *y);
242 }
243}
244
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200245// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700246// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
247// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200248template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700249void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200250 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200251 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
252 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200253 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700254 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700255 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200256 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200257 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700258 if (y)
259 result->points.emplace_back(x, static_cast<float>(*y));
260 }
261}
262
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200263// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700264// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
265// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200266template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700267void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200268 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200269 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
270 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200271 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700272 TimeSeries* result) {
273 ResultType sum = 0;
274 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200275 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200276 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700277 if (y)
278 sum += *y;
279 result->points.emplace_back(x, static_cast<float>(sum));
tereliusccbbf8d2016-08-10 07:34:28 -0700280 }
281}
282
terelius6addf492016-08-23 17:34:07 -0700283// Calculates a moving average of |data| and stores the result in a TimeSeries.
284// A data point is generated every |step| microseconds from |begin_time|
285// to |end_time|. The value of each data point is the average of the data
286// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200287template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700288void MovingAverage(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200289 rtc::FunctionView<float(int64_t)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200290 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200291 const IterableType& data_view,
292 int64_t begin_time,
293 int64_t end_time,
294 int64_t window_duration_us,
295 int64_t step,
296 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700297 size_t window_index_begin = 0;
298 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700299 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700300
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200301 for (int64_t t = begin_time; t < end_time + step; t += step) {
302 while (window_index_end < data_view.size() &&
303 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200304 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700305 if (value)
306 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700307 ++window_index_end;
308 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200309 while (window_index_begin < data_view.size() &&
310 data_view[window_index_begin].log_time_us() <
311 t - window_duration_us) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200312 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700313 if (value)
314 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700315 ++window_index_begin;
316 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800317 float window_duration_s =
318 static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200319 float x = fx(t);
terelius53dc23c2017-03-13 05:24:05 -0700320 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700321 result->points.emplace_back(x, y);
322 }
323}
324
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800325const char kUnknownEnumValue[] = "unknown";
326
327const char kIceCandidateTypeLocal[] = "local";
328const char kIceCandidateTypeStun[] = "stun";
329const char kIceCandidateTypePrflx[] = "prflx";
330const char kIceCandidateTypeRelay[] = "relay";
331
332const char kProtocolUdp[] = "udp";
333const char kProtocolTcp[] = "tcp";
334const char kProtocolSsltcp[] = "ssltcp";
335const char kProtocolTls[] = "tls";
336
337const char kAddressFamilyIpv4[] = "ipv4";
338const char kAddressFamilyIpv6[] = "ipv6";
339
340const char kNetworkTypeEthernet[] = "ethernet";
341const char kNetworkTypeLoopback[] = "loopback";
342const char kNetworkTypeWifi[] = "wifi";
343const char kNetworkTypeVpn[] = "vpn";
344const char kNetworkTypeCellular[] = "cellular";
345
346std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
347 switch (type) {
348 case webrtc::IceCandidateType::kLocal:
349 return kIceCandidateTypeLocal;
350 case webrtc::IceCandidateType::kStun:
351 return kIceCandidateTypeStun;
352 case webrtc::IceCandidateType::kPrflx:
353 return kIceCandidateTypePrflx;
354 case webrtc::IceCandidateType::kRelay:
355 return kIceCandidateTypeRelay;
356 default:
357 return kUnknownEnumValue;
358 }
359}
360
361std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
362 switch (protocol) {
363 case webrtc::IceCandidatePairProtocol::kUdp:
364 return kProtocolUdp;
365 case webrtc::IceCandidatePairProtocol::kTcp:
366 return kProtocolTcp;
367 case webrtc::IceCandidatePairProtocol::kSsltcp:
368 return kProtocolSsltcp;
369 case webrtc::IceCandidatePairProtocol::kTls:
370 return kProtocolTls;
371 default:
372 return kUnknownEnumValue;
373 }
374}
375
376std::string GetAddressFamilyAsString(
377 webrtc::IceCandidatePairAddressFamily family) {
378 switch (family) {
379 case webrtc::IceCandidatePairAddressFamily::kIpv4:
380 return kAddressFamilyIpv4;
381 case webrtc::IceCandidatePairAddressFamily::kIpv6:
382 return kAddressFamilyIpv6;
383 default:
384 return kUnknownEnumValue;
385 }
386}
387
388std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
389 switch (type) {
390 case webrtc::IceCandidateNetworkType::kEthernet:
391 return kNetworkTypeEthernet;
392 case webrtc::IceCandidateNetworkType::kLoopback:
393 return kNetworkTypeLoopback;
394 case webrtc::IceCandidateNetworkType::kWifi:
395 return kNetworkTypeWifi;
396 case webrtc::IceCandidateNetworkType::kVpn:
397 return kNetworkTypeVpn;
398 case webrtc::IceCandidateNetworkType::kCellular:
399 return kNetworkTypeCellular;
400 default:
401 return kUnknownEnumValue;
402 }
403}
404
405std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200406 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800407 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
408 // represents a pair of a local server-reflexive candidate on a WiFi network
409 // and a remote relay candidate using TCP as the relay protocol on a cell
410 // network, when the candidate pair communicates over UDP using IPv4.
411 std::stringstream ss;
412 std::string local_candidate_type =
413 GetIceCandidateTypeAsString(config.local_candidate_type);
414 std::string remote_candidate_type =
415 GetIceCandidateTypeAsString(config.remote_candidate_type);
416 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
417 local_candidate_type +=
418 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
419 }
420 ss << local_candidate_type << ":"
421 << GetNetworkTypeAsString(config.local_network_type) << ":"
422 << GetAddressFamilyAsString(config.local_address_family) << "->"
423 << remote_candidate_type << ":"
424 << GetAddressFamilyAsString(config.remote_address_family) << "@"
425 << GetProtocolAsString(config.candidate_pair_protocol);
426 return ss.str();
427}
428
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200429std::string GetDirectionAsString(PacketDirection direction) {
430 if (direction == kIncomingPacket) {
431 return "Incoming";
432 } else {
433 return "Outgoing";
434 }
435}
436
437std::string GetDirectionAsShortString(PacketDirection direction) {
438 if (direction == kIncomingPacket) {
439 return "In";
440 } else {
441 return "Out";
442 }
443}
444
terelius54ce6802016-07-13 06:44:41 -0700445} // namespace
446
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200447EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log,
448 bool normalize_time)
449 : parsed_log_(log),
450 window_duration_(250000),
451 step_(10000),
452 normalize_time_(normalize_time) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200453 begin_time_ = parsed_log_.first_timestamp();
454 end_time_ = parsed_log_.last_timestamp();
455 if (end_time_ < begin_time_) {
456 RTC_LOG(LS_WARNING) << "No useful events in the log.";
457 begin_time_ = end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000458 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200459 call_duration_s_ = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200460
461 const auto& log_start_events = parsed_log_.start_log_events();
462 const auto& log_end_events = parsed_log_.stop_log_events();
463 auto start_iter = log_start_events.begin();
464 auto end_iter = log_end_events.begin();
465 while (start_iter != log_start_events.end()) {
466 int64_t start = start_iter->log_time_us();
467 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200468 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200469 if (start_iter != log_start_events.end())
470 next_start.emplace(start_iter->log_time_us());
471 if (end_iter != log_end_events.end() &&
472 end_iter->log_time_us() <=
473 next_start.value_or(std::numeric_limits<int64_t>::max())) {
474 int64_t end = end_iter->log_time_us();
475 RTC_DCHECK_LE(start, end);
476 log_segments_.push_back(std::make_pair(start, end));
477 ++end_iter;
478 } else {
479 // we're missing an end event. Assume that it occurred just before the
480 // next start.
481 log_segments_.push_back(
482 std::make_pair(start, next_start.value_or(end_time_)));
483 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700484 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100485 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200486 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700487}
488
Sebastian Janssone4be6da2018-02-15 16:51:41 +0100489class BitrateObserver : public NetworkChangedObserver,
Stefan Holmer13181032016-07-29 14:48:54 +0200490 public RemoteBitrateObserver {
491 public:
492 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
493
494 void OnNetworkChanged(uint32_t bitrate_bps,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200495 uint8_t fraction_lost,
minyue78b4d562016-11-30 04:47:39 -0800496 int64_t rtt_ms,
497 int64_t probing_interval_ms) override {
Stefan Holmer13181032016-07-29 14:48:54 +0200498 last_bitrate_bps_ = bitrate_bps;
499 bitrate_updated_ = true;
500 }
501
502 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
503 uint32_t bitrate) override {}
504
505 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
506 bool GetAndResetBitrateUpdated() {
507 bool bitrate_updated = bitrate_updated_;
508 bitrate_updated_ = false;
509 return bitrate_updated;
510 }
511
512 private:
513 uint32_t last_bitrate_bps_;
514 bool bitrate_updated_;
515};
516
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200517int64_t EventLogAnalyzer::ToCallTimeUs(int64_t timestamp) const {
518 int64_t begin_time = 0;
519 if (normalize_time_) {
520 begin_time = begin_time_;
521 }
522 return timestamp - begin_time;
523}
524
525float EventLogAnalyzer::ToCallTimeSec(int64_t timestamp) const {
526 return static_cast<float>(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100527}
528
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200529void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700530 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200531 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
532 // Filter on SSRC.
533 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700534 continue;
terelius54ce6802016-07-13 06:44:41 -0700535 }
terelius54ce6802016-07-13 06:44:41 -0700536
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200537 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
538 LineStyle::kBar);
539 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200540 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200541 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200542 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
543 return this->ToCallTimeSec(packet.log_time_us());
544 };
545 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
546 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700547 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700548 }
549
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200550 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
551 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700552 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
553 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200554 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700555}
556
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200557template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700558void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700559 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200560 const IterableType& packets,
561 const std::string& label) {
562 TimeSeries time_series(label, LineStyle::kStep);
563 for (size_t i = 0; i < packets.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200564 float x = ToCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200565 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700566 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200567 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700568}
569
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200570void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
571 Plot* plot) {
572 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
573 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
574 continue;
575 std::string label =
576 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
577 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
578 }
579 std::string label =
580 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
581 if (direction == kIncomingPacket) {
582 CreateAccumulatedPacketsTimeSeries(
583 plot, parsed_log_.incoming_rtcp_packets(), label);
584 } else {
585 CreateAccumulatedPacketsTimeSeries(
586 plot, parsed_log_.outgoing_rtcp_packets(), label);
587 }
philipelccd74892016-09-05 02:46:25 -0700588
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200589 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
590 kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700591 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200592 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
593 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700594}
595
terelius54ce6802016-07-13 06:44:41 -0700596// For each SSRC, plot the time between the consecutive playouts.
597void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200598 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
599 uint32_t ssrc = playout_stream.first;
600 if (!MatchingSsrc(ssrc, desired_ssrc_))
601 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200602 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200603 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200604 for (const auto& playout_event : playout_stream.second) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200605 float x = ToCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200606 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200607 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200608 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200609 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200610 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700611 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200612 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700613 }
614
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200615 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
616 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700617 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
618 kTopMargin);
619 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700620}
621
ivocaac9d6f2016-09-22 07:01:47 -0700622// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200623void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
624 Plot* plot) {
625 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
626 if (!IsAudioSsrc(direction, stream.ssrc))
627 continue;
628 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
629 LineStyle::kLine);
630 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700631 if (packet.header.extension.hasAudioLevel) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200632 float x = ToCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700633 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
634 // Here we convert it to dBov.
635 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200636 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700637 }
638 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200639 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700640 }
641
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200642 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
643 kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200644 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200645 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700646}
647
terelius54ce6802016-07-13 06:44:41 -0700648// For each SSRC, plot the time between the consecutive playouts.
649void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200650 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
651 // Filter on SSRC.
652 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700653 continue;
terelius54ce6802016-07-13 06:44:41 -0700654 }
terelius54ce6802016-07-13 06:44:41 -0700655
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200656 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
657 LineStyle::kBar);
658 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
659 const LoggedRtpPacketIncoming& new_packet) {
660 int64_t diff =
661 WrappingDifference(new_packet.rtp.header.sequenceNumber,
662 old_packet.rtp.header.sequenceNumber, 1ul << 16);
663 return diff;
664 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200665 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
666 return this->ToCallTimeSec(packet.log_time_us());
667 };
668 ProcessPairs<LoggedRtpPacketIncoming, float>(
669 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
670 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700671 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700672 }
673
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200674 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
675 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700676 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
677 kTopMargin);
678 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700679}
680
Stefan Holmer99f8e082016-09-09 13:37:50 +0200681void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200682 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
683 const std::vector<LoggedRtpPacketIncoming>& packets =
684 stream.incoming_packets;
685 // Filter on SSRC.
686 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200687 continue;
688 }
689
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200690 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
691 LineStyle::kLine, PointStyle::kHighlight);
692 // TODO(terelius): Should the window and step size be read from the class
693 // instead?
694 const int64_t kWindowUs = 1000000;
695 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100696 SeqNumUnwrapper<uint16_t> unwrapper_;
697 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800698 size_t window_index_begin = 0;
699 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200700 uint64_t highest_seq_number =
701 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
702 uint64_t highest_prior_seq_number =
703 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800704
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200705 for (int64_t t = begin_time_; t < end_time_ + kStep; t += kStep) {
706 while (window_index_end < packets.size() &&
707 packets[window_index_end].rtp.log_time_us() < t) {
708 uint64_t sequence_number = unwrapper_.Unwrap(
709 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800710 highest_seq_number = std::max(highest_seq_number, sequence_number);
711 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200712 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200713 while (window_index_begin < packets.size() &&
714 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
715 uint64_t sequence_number = prior_unwrapper_.Unwrap(
716 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800717 highest_prior_seq_number =
718 std::max(highest_prior_seq_number, sequence_number);
719 ++window_index_begin;
720 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200721 float x = ToCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200722 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800723 if (expected_packets > 0) {
724 int64_t received_packets = window_index_end - window_index_begin;
725 int64_t lost_packets = expected_packets - received_packets;
726 float y = static_cast<float>(lost_packets) / expected_packets * 100;
727 time_series.points.emplace_back(x, y);
728 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200729 }
philipel35ba9bd2017-04-19 05:58:51 -0700730 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200731 }
732
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200733 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
734 kLeftMargin, kRightMargin);
Stefan Holmer99f8e082016-09-09 13:37:50 +0200735 plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
736 kTopMargin);
737 plot->SetTitle("Estimated incoming loss rate");
738}
739
terelius2ee076d2017-08-15 02:04:02 -0700740void EventLogAnalyzer::CreateIncomingDelayDeltaGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200741 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(kIncomingPacket)) {
742 // Filter on SSRC.
743 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
744 IsAudioSsrc(kIncomingPacket, stream.ssrc) ||
745 !IsVideoSsrc(kIncomingPacket, stream.ssrc) ||
746 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700747 continue;
748 }
terelius54ce6802016-07-13 06:44:41 -0700749
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200750 TimeSeries capture_time_data(
751 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
752 LineStyle::kBar);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200753 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
754 return this->ToCallTimeSec(packet.log_time_us());
755 };
756 ProcessPairs<LoggedRtpPacket, double>(
757 ToCallTime, NetworkDelayDiff_CaptureTime, stream.packet_view,
758 &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700759 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700760
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200761 TimeSeries send_time_data(
762 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
763 LineStyle::kBar);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200764 ProcessPairs<LoggedRtpPacket, double>(ToCallTime,
765 NetworkDelayDiff_AbsSendTime,
766 stream.packet_view, &send_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700767 plot->AppendTimeSeries(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700768 }
769
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200770 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
771 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700772 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
773 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700774 plot->SetTitle("Network latency difference between consecutive packets");
terelius54ce6802016-07-13 06:44:41 -0700775}
776
terelius2ee076d2017-08-15 02:04:02 -0700777void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200778 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(kIncomingPacket)) {
779 // Filter on SSRC.
780 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
781 IsAudioSsrc(kIncomingPacket, stream.ssrc) ||
782 !IsVideoSsrc(kIncomingPacket, stream.ssrc) ||
783 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700784 continue;
785 }
terelius54ce6802016-07-13 06:44:41 -0700786
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200787 TimeSeries capture_time_data(
788 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
789 LineStyle::kLine);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200790 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
791 return this->ToCallTimeSec(packet.log_time_us());
792 };
793 AccumulatePairs<LoggedRtpPacket, double>(
794 ToCallTime, NetworkDelayDiff_CaptureTime, stream.packet_view,
795 &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700796 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700797
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200798 TimeSeries send_time_data(
799 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
800 LineStyle::kLine);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200801 AccumulatePairs<LoggedRtpPacket, double>(
802 ToCallTime, NetworkDelayDiff_AbsSendTime, stream.packet_view,
803 &send_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700804 plot->AppendTimeSeries(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700805 }
806
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200807 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
808 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700809 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
810 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700811 plot->SetTitle("Network latency (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700812}
813
tereliusf736d232016-08-04 10:00:11 -0700814// Plot the fraction of packets lost (as perceived by the loss-based BWE).
815void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100816 TimeSeries time_series("Fraction lost", LineStyle::kLine,
817 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200818 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200819 float x = ToCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200820 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700821 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700822 }
tereliusf736d232016-08-04 10:00:11 -0700823
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200824 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200825 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
826 kLeftMargin, kRightMargin);
tereliusf736d232016-08-04 10:00:11 -0700827 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
828 kTopMargin);
829 plot->SetTitle("Reported packet loss");
830}
831
terelius54ce6802016-07-13 06:44:41 -0700832// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200833void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
834 // TODO(terelius): This could be provided by the parser.
835 std::multimap<int64_t, size_t> packets_in_order;
836 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
837 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
838 packets_in_order.insert(
839 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700840 }
841
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200842 auto window_begin = packets_in_order.begin();
843 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700844 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700845
846 // Calculate a moving average of the bitrate and store in a TimeSeries.
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100847 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200848 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
849 while (window_end != packets_in_order.end() && window_end->first < time) {
850 bytes_in_window += window_end->second;
851 ++window_end;
terelius54ce6802016-07-13 06:44:41 -0700852 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200853 while (window_begin != packets_in_order.end() &&
854 window_begin->first < time - window_duration_) {
855 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
856 bytes_in_window -= window_begin->second;
857 ++window_begin;
858 }
859 float window_duration_in_seconds =
860 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200861 float x = ToCallTimeSec(time);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200862 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
863 bitrate_series.points.emplace_back(x, y);
864 }
865 plot->AppendTimeSeries(std::move(bitrate_series));
866
867 // Overlay the outgoing REMB over incoming bitrate.
868 TimeSeries remb_series("Remb", LineStyle::kStep);
869 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200870 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200871 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
872 remb_series.points.emplace_back(x, y);
873 }
874 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
875
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200876 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
877 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200878 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
879 plot->SetTitle("Incoming RTP bitrate");
880}
881
882// Plot the total bandwidth used by all RTP streams.
883void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
884 bool show_detector_state,
885 bool show_alr_state) {
886 // TODO(terelius): This could be provided by the parser.
887 std::multimap<int64_t, size_t> packets_in_order;
888 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
889 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
890 packets_in_order.insert(
891 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
892 }
893
894 auto window_begin = packets_in_order.begin();
895 auto window_end = packets_in_order.begin();
896 size_t bytes_in_window = 0;
897
898 // Calculate a moving average of the bitrate and store in a TimeSeries.
899 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
900 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
901 while (window_end != packets_in_order.end() && window_end->first < time) {
902 bytes_in_window += window_end->second;
903 ++window_end;
904 }
905 while (window_begin != packets_in_order.end() &&
906 window_begin->first < time - window_duration_) {
907 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
908 bytes_in_window -= window_begin->second;
909 ++window_begin;
terelius54ce6802016-07-13 06:44:41 -0700910 }
911 float window_duration_in_seconds =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800912 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200913 float x = ToCallTimeSec(time);
terelius54ce6802016-07-13 06:44:41 -0700914 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
philipel35ba9bd2017-04-19 05:58:51 -0700915 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700916 }
philipel35ba9bd2017-04-19 05:58:51 -0700917 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700918
terelius8058e582016-07-25 01:32:41 -0700919 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200920 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
921 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200922 float x = ToCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200923 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
924 loss_series.points.emplace_back(x, y);
925 }
philipel10fc0e62017-04-11 01:50:23 -0700926
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200927 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
928 IntervalSeries overusing_series("Overusing", "#ff8e82",
929 IntervalSeries::kHorizontal);
930 IntervalSeries underusing_series("Underusing", "#5092fc",
931 IntervalSeries::kHorizontal);
932 IntervalSeries normal_series("Normal", "#c4ffc4",
933 IntervalSeries::kHorizontal);
934 IntervalSeries* last_series = &normal_series;
935 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700936
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200937 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700938
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200939 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200940 float x = ToCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200941 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700942
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200943 if (last_detector_state != delay_update.detector_state) {
944 last_series->intervals.emplace_back(last_detector_switch, x);
945 last_detector_state = delay_update.detector_state;
946 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700947
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200948 switch (delay_update.detector_state) {
949 case BandwidthUsage::kBwNormal:
950 last_series = &normal_series;
951 break;
952 case BandwidthUsage::kBwUnderusing:
953 last_series = &underusing_series;
954 break;
955 case BandwidthUsage::kBwOverusing:
956 last_series = &overusing_series;
957 break;
958 case BandwidthUsage::kLast:
959 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200960 }
961 }
philipel23c7f252017-07-14 06:30:03 -0700962
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200963 delay_series.points.emplace_back(x, y);
964 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200965
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200966 RTC_CHECK(last_series);
967 last_series->intervals.emplace_back(last_detector_switch, end_time_);
968
969 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
970 PointStyle::kHighlight);
971 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200972 float x = ToCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200973 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
974 created_series.points.emplace_back(x, y);
975 }
976
977 TimeSeries result_series("Probing results.", LineStyle::kNone,
978 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200979 for (auto& result : parsed_log_.bwe_probe_success_events()) {
980 float x = ToCallTimeSec(result.log_time_us());
981 float y = static_cast<float>(result.bitrate_bps) / 1000;
982 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200983 }
984
985 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
986 bool previously_in_alr = false;
987 int64_t alr_start = 0;
988 for (auto& alr : parsed_log_.alr_state_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200989 float y = ToCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200990 if (!previously_in_alr && alr.in_alr) {
991 alr_start = alr.log_time_us();
992 previously_in_alr = true;
993 } else if (previously_in_alr && !alr.in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200994 float x = ToCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100995 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200996 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +0000997 }
Björn Tereliusff612732018-04-25 14:23:01 +0000998 }
999
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001000 if (previously_in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001001 float x = ToCallTimeSec(alr_start);
1002 float y = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001003 alr_state.intervals.emplace_back(x, y);
1004 }
1005
1006 if (show_detector_state) {
1007 plot->AppendIntervalSeries(std::move(overusing_series));
1008 plot->AppendIntervalSeries(std::move(underusing_series));
1009 plot->AppendIntervalSeries(std::move(normal_series));
1010 }
1011
1012 if (show_alr_state) {
1013 plot->AppendIntervalSeries(std::move(alr_state));
1014 }
1015 plot->AppendTimeSeries(std::move(loss_series));
1016 plot->AppendTimeSeries(std::move(delay_series));
1017 plot->AppendTimeSeries(std::move(created_series));
1018 plot->AppendTimeSeries(std::move(result_series));
1019
1020 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001021 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001022 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001023 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001024 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001025 remb_series.points.emplace_back(x, y);
1026 }
1027 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1028
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001029 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1030 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001031 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001032 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001033}
1034
1035// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001036void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1037 Plot* plot) {
1038 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1039 // Filter on SSRC.
1040 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001041 continue;
terelius54ce6802016-07-13 06:44:41 -07001042 }
1043
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001044 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1045 LineStyle::kLine);
1046 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1047 return packet.total_length * 8.0 / 1000.0;
1048 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001049 auto ToCallTime = [this](int64_t time) {
1050 return this->ToCallTimeSec(time);
1051 };
terelius53dc23c2017-03-13 05:24:05 -07001052 MovingAverage<LoggedRtpPacket, double>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001053 ToCallTime, GetPacketSizeKilobits, stream.packet_view, begin_time_,
1054 end_time_, window_duration_, step_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001055 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001056 }
1057
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001058 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1059 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001060 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001061 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001062}
1063
Bjorn Terelius28db2662017-10-04 14:22:43 +02001064void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001065 using RtpPacketType = LoggedRtpPacketOutgoing;
1066 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001067
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001068 // TODO(terelius): This could be provided by the parser.
1069 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1070 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1071 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1072 outgoing_rtp.insert(
1073 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001074 }
1075
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001076 const std::vector<TransportFeedbackType>& incoming_rtcp =
1077 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001078
1079 SimulatedClock clock(0);
1080 BitrateObserver observer;
1081 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001082 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001083 PacedSender pacer(&clock, &packet_router, &null_event_log);
1084 SendSideCongestionController cc(&clock, &observer, &null_event_log, &pacer);
Stefan Holmer13181032016-07-29 14:48:54 +02001085 // TODO(holmer): Log the call config and use that here instead.
1086 static const uint32_t kDefaultStartBitrateBps = 300000;
1087 cc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1088
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001089 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1090 PointStyle::kHighlight);
1091 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1092 PointStyle::kHighlight);
1093 TimeSeries acked_estimate_time_series(
1094 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001095
1096 auto rtp_iterator = outgoing_rtp.begin();
1097 auto rtcp_iterator = incoming_rtcp.begin();
1098
1099 auto NextRtpTime = [&]() {
1100 if (rtp_iterator != outgoing_rtp.end())
1101 return static_cast<int64_t>(rtp_iterator->first);
1102 return std::numeric_limits<int64_t>::max();
1103 };
1104
1105 auto NextRtcpTime = [&]() {
1106 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001107 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001108 return std::numeric_limits<int64_t>::max();
1109 };
1110
1111 auto NextProcessTime = [&]() {
1112 if (rtcp_iterator != incoming_rtcp.end() ||
1113 rtp_iterator != outgoing_rtp.end()) {
1114 return clock.TimeInMicroseconds() +
1115 std::max<int64_t>(cc.TimeUntilNextProcess() * 1000, 0);
1116 }
1117 return std::numeric_limits<int64_t>::max();
1118 };
1119
Stefan Holmer492ee282016-10-27 17:19:20 +02001120 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001121#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1122 // The event_log_visualizer should normally not be compiled with
1123 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1124 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1125 // and piping the output to plot_dynamics.py can be used as a hack to get the
1126 // internal state of various BWE components. In this case, it is important
1127 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1128 // SendSideCongestionController since that would lead to duplicate outputs.
1129 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
1130 rtc::MakeUnique<BitrateEstimator>());
1131#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001132 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
Stefan Holmer492ee282016-10-27 17:19:20 +02001133 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001134 while (time_us != std::numeric_limits<int64_t>::max()) {
1135 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1136 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001137 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001138 cc.OnTransportFeedback(rtcp_iterator->transport_feedback);
1139 std::vector<PacketFeedback> feedback = cc.GetTransportFeedbackVector();
1140 SortPacketFeedbackVector(&feedback);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001141 absl::optional<uint32_t> bitrate_bps;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001142 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001143#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001144 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001145#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001146 for (const PacketFeedback& packet : feedback)
1147 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1148 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
Stefan Holmer13181032016-07-29 14:48:54 +02001149 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001150 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001151 float y = bitrate_bps.value_or(0) / 1000;
1152 acked_time_series.points.emplace_back(x, y);
1153#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1154 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1155 acked_estimate_time_series.points.emplace_back(x, y);
1156#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001157 ++rtcp_iterator;
1158 }
1159 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001160 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001161 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1162 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1163 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
1164 cc.AddPacket(rtp_packet.rtp.header.ssrc,
1165 rtp_packet.rtp.header.extension.transportSequenceNumber,
1166 rtp_packet.rtp.total_length, PacedPacketInfo());
Stefan Holmer13181032016-07-29 14:48:54 +02001167 rtc::SentPacket sent_packet(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001168 rtp_packet.rtp.header.extension.transportSequenceNumber,
1169 rtp_packet.rtp.log_time_us() / 1000);
Stefan Holmer13181032016-07-29 14:48:54 +02001170 cc.OnSentPacket(sent_packet);
1171 }
1172 ++rtp_iterator;
1173 }
stefanc3de0332016-08-02 07:22:17 -07001174 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1175 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Stefan Holmer13181032016-07-29 14:48:54 +02001176 cc.Process();
stefanc3de0332016-08-02 07:22:17 -07001177 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001178 if (observer.GetAndResetBitrateUpdated() ||
1179 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001180 uint32_t y = observer.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001181 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001182 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001183 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001184 }
1185 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1186 }
1187 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001188 plot->AppendTimeSeries(std::move(time_series));
1189 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001190 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001191
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001192 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1193 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001194 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001195 plot->SetTitle("Simulated send-side BWE behavior");
1196}
1197
1198void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001199 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001200 class RembInterceptingPacketRouter : public PacketRouter {
1201 public:
1202 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1203 uint32_t bitrate_bps) override {
1204 last_bitrate_bps_ = bitrate_bps;
1205 bitrate_updated_ = true;
1206 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1207 }
1208 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1209 bool GetAndResetBitrateUpdated() {
1210 bool bitrate_updated = bitrate_updated_;
1211 bitrate_updated_ = false;
1212 return bitrate_updated;
1213 }
1214
1215 private:
1216 uint32_t last_bitrate_bps_;
1217 bool bitrate_updated_;
1218 };
1219
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001220 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001221
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001222 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1223 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1224 for (const auto& rtp_packet : stream.incoming_packets)
1225 incoming_rtp.insert(
1226 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001227 }
1228 }
1229
1230 SimulatedClock clock(0);
1231 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001232 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001233 // Is this intentional?
1234 ReceiveSideCongestionController rscc(&clock, &packet_router);
1235 // TODO(holmer): Log the call config and use that here instead.
1236 // static const uint32_t kDefaultStartBitrateBps = 300000;
1237 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1238
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001239 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1240 PointStyle::kHighlight);
1241 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001242
1243 RateStatistics acked_bitrate(250, 8000);
1244 int64_t last_update_us = 0;
1245 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001246 const RtpPacketType& packet = *kv.second;
1247 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1248 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1249 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001250 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001251 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001252 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001253 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001254 if (bitrate_bps) {
1255 uint32_t y = *bitrate_bps / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001256 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001257 acked_time_series.points.emplace_back(x, y);
1258 }
1259 if (packet_router.GetAndResetBitrateUpdated() ||
1260 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1261 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001262 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001263 time_series.points.emplace_back(x, y);
1264 last_update_us = clock.TimeInMicroseconds();
1265 }
1266 }
1267 // Add the data set to the plot.
1268 plot->AppendTimeSeries(std::move(time_series));
1269 plot->AppendTimeSeries(std::move(acked_time_series));
1270
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001271 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1272 kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001273 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1274 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001275}
1276
tereliuse34c19c2016-08-15 08:47:14 -07001277void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001278 using RtpPacketType = LoggedRtpPacketOutgoing;
1279 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
stefanc3de0332016-08-02 07:22:17 -07001280
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001281 // TODO(terelius): This could be provided by the parser.
1282 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1283 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1284 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1285 outgoing_rtp.insert(
1286 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
stefanc3de0332016-08-02 07:22:17 -07001287 }
1288
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001289 const std::vector<TransportFeedbackType>& incoming_rtcp =
1290 parsed_log_.transport_feedbacks(kIncomingPacket);
stefanc3de0332016-08-02 07:22:17 -07001291
1292 SimulatedClock clock(0);
elad.alon5bbf43f2017-03-09 06:40:08 -08001293 TransportFeedbackAdapter feedback_adapter(&clock);
stefanc3de0332016-08-02 07:22:17 -07001294
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001295 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1296 PointStyle::kHighlight);
1297 TimeSeries time_series("Network Delay Change", LineStyle::kLine,
1298 PointStyle::kHighlight);
stefanc3de0332016-08-02 07:22:17 -07001299 int64_t estimated_base_delay_ms = std::numeric_limits<int64_t>::max();
1300
1301 auto rtp_iterator = outgoing_rtp.begin();
1302 auto rtcp_iterator = incoming_rtcp.begin();
1303
1304 auto NextRtpTime = [&]() {
1305 if (rtp_iterator != outgoing_rtp.end())
1306 return static_cast<int64_t>(rtp_iterator->first);
1307 return std::numeric_limits<int64_t>::max();
1308 };
1309
1310 auto NextRtcpTime = [&]() {
1311 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001312 return static_cast<int64_t>(rtcp_iterator->log_time_us());
stefanc3de0332016-08-02 07:22:17 -07001313 return std::numeric_limits<int64_t>::max();
1314 };
1315
1316 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
stefana0a8ed72017-09-06 02:06:32 -07001317 int64_t prev_y = 0;
stefanc3de0332016-08-02 07:22:17 -07001318 while (time_us != std::numeric_limits<int64_t>::max()) {
1319 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1320 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
1321 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001322 feedback_adapter.OnTransportFeedback(rtcp_iterator->transport_feedback);
1323 std::vector<PacketFeedback> feedback =
1324 feedback_adapter.GetTransportFeedbackVector();
1325 SortPacketFeedbackVector(&feedback);
1326 for (const PacketFeedback& packet : feedback) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001327 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001328 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1329 late_feedback_series.points.emplace_back(x, prev_y);
1330 continue;
stefanc3de0332016-08-02 07:22:17 -07001331 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001332 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1333 prev_y = y;
1334 estimated_base_delay_ms = std::min(y, estimated_base_delay_ms);
1335 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001336 }
1337 ++rtcp_iterator;
1338 }
1339 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1340 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001341 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1342 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1343 feedback_adapter.AddPacket(
1344 rtp_packet.rtp.header.ssrc,
1345 rtp_packet.rtp.header.extension.transportSequenceNumber,
1346 rtp_packet.rtp.total_length, PacedPacketInfo());
stefanc3de0332016-08-02 07:22:17 -07001347 feedback_adapter.OnSentPacket(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001348 rtp_packet.rtp.header.extension.transportSequenceNumber,
1349 rtp_packet.rtp.log_time_us() / 1000);
stefanc3de0332016-08-02 07:22:17 -07001350 }
1351 ++rtp_iterator;
1352 }
1353 time_us = std::min(NextRtpTime(), NextRtcpTime());
1354 }
1355 // We assume that the base network delay (w/o queues) is the min delay
1356 // observed during the call.
1357 for (TimeSeriesPoint& point : time_series.points)
1358 point.y -= estimated_base_delay_ms;
stefana0a8ed72017-09-06 02:06:32 -07001359 for (TimeSeriesPoint& point : late_feedback_series.points)
1360 point.y -= estimated_base_delay_ms;
stefanc3de0332016-08-02 07:22:17 -07001361 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001362 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1363 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001364
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001365 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1366 kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001367 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
1368 plot->SetTitle("Network Delay Change.");
1369}
stefan08383272016-12-20 08:51:52 -08001370
Bjorn Terelius0295a962017-10-25 17:42:41 +02001371void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001372 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1373 const std::vector<LoggedRtpPacketOutgoing>& packets =
1374 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001375
1376 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001377 RTC_LOG(LS_WARNING)
1378 << "Can't estimate a the RTP clock frequency or the "
1379 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001380 continue;
1381 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001382 int64_t end_time_us = log_segments_.empty()
1383 ? std::numeric_limits<int64_t>::max()
1384 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001385 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001386 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001387 if (!estimated_frequency)
1388 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001389 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1390 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001391 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001392 << "Video stream should use a 90 kHz clock but appears to use "
1393 << *estimated_frequency / 1000 << ". Discarding.";
1394 continue;
1395 }
1396
1397 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001398 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001399 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001400 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001401 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1402 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001403 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1404 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1405 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001406 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001407 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001408 first_capture_timestamp) /
1409 *estimated_frequency * 1000;
1410 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001411 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1412 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001413 float x = ToCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001414 float y = send_time_ms - capture_time_ms;
1415 pacer_delay_series.points.emplace_back(x, y);
1416 }
1417 plot->AppendTimeSeries(std::move(pacer_delay_series));
1418 }
1419
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001420 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1421 kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001422 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1423 plot->SetTitle(
1424 "Delay from capture to send time. (First packet normalized to 0.)");
1425}
1426
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001427void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1428 Plot* plot) {
1429 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1430 TimeSeries rtp_timestamps(
1431 GetStreamName(direction, stream.ssrc) + " capture-time",
1432 LineStyle::kLine, PointStyle::kHighlight);
1433 for (const auto& packet : stream.packet_view) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001434 float x = ToCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001435 float y = packet.header.timestamp;
1436 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001437 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001438 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001439
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001440 TimeSeries rtcp_timestamps(
1441 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1442 LineStyle::kLine, PointStyle::kHighlight);
1443 // TODO(terelius): Why only sender reports?
1444 const auto& sender_reports = parsed_log_.sender_reports(direction);
1445 for (const auto& rtcp : sender_reports) {
1446 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1447 continue;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001448 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001449 float y = rtcp.sr.rtp_timestamp();
1450 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001451 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001452 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001453 }
1454
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001455 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1456 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001457 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1458 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001459}
michaelt6e5b2192017-02-22 07:33:27 -08001460
1461void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001462 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1463 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001464 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001465 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001466 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001467 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001468 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001469 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001470 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001471 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1472 return this->ToCallTimeSec(packet.log_time_us());
1473 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001474 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001475 ToCallTime, GetAnaBitrateBps,
1476 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001477 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001478 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1479 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001480 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1481 plot->SetTitle("Reported audio encoder target bitrate");
1482}
1483
1484void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001485 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1486 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001487 auto GetAnaFrameLengthMs =
1488 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001489 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001490 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001491 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001492 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001493 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001494 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1495 return this->ToCallTimeSec(packet.log_time_us());
1496 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001497 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001498 ToCallTime, GetAnaFrameLengthMs,
1499 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001500 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001501 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1502 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001503 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1504 plot->SetTitle("Reported audio encoder frame length");
1505}
1506
terelius2ee076d2017-08-15 02:04:02 -07001507void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001508 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001509 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001510 auto GetAnaPacketLoss =
1511 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001512 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001513 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001514 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001515 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001516 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001517 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1518 return this->ToCallTimeSec(packet.log_time_us());
1519 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001520 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001521 ToCallTime, GetAnaPacketLoss,
1522 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001523 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001524 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1525 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001526 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1527 kTopMargin);
1528 plot->SetTitle("Reported audio encoder lost packets");
1529}
1530
1531void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001532 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1533 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001534 auto GetAnaFecEnabled =
1535 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001536 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001537 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001538 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001539 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001540 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001541 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1542 return this->ToCallTimeSec(packet.log_time_us());
1543 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001544 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001545 ToCallTime, GetAnaFecEnabled,
1546 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001547 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001548 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1549 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001550 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1551 plot->SetTitle("Reported audio encoder FEC");
1552}
1553
1554void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001555 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1556 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001557 auto GetAnaDtxEnabled =
1558 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001559 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001560 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001561 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001562 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001563 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001564 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1565 return this->ToCallTimeSec(packet.log_time_us());
1566 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001567 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001568 ToCallTime, GetAnaDtxEnabled,
1569 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001570 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001571 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1572 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001573 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1574 plot->SetTitle("Reported audio encoder DTX");
1575}
1576
1577void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001578 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1579 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001580 auto GetAnaNumChannels =
1581 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001582 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001583 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001584 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001585 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001586 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001587 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1588 return this->ToCallTimeSec(packet.log_time_us());
1589 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001590 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001591 ToCallTime, GetAnaNumChannels,
1592 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001593 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001594 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1595 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001596 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1597 kBottomMargin, kTopMargin);
1598 plot->SetTitle("Reported audio encoder number of channels");
1599}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001600
1601class NetEqStreamInput : public test::NetEqInput {
1602 public:
1603 // Does not take any ownership, and all pointers must refer to valid objects
1604 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001605 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001606 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001607 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001608 : packet_stream_(*packet_stream),
1609 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001610 output_events_it_(output_events->begin()),
1611 output_events_end_(output_events->end()),
1612 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001613 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001614 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001615 }
1616
Danil Chapovalov431abd92018-06-18 12:54:17 +02001617 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001618 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001619 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001620 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001621 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001622 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001623 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001624 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001625 }
1626
Danil Chapovalov431abd92018-06-18 12:54:17 +02001627 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001628 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001629 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001630 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001631 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001632 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001633 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001634 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001635 }
1636
1637 std::unique_ptr<PacketData> PopPacket() override {
1638 if (packet_stream_it_ == packet_stream_.end()) {
1639 return std::unique_ptr<PacketData>();
1640 }
1641 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001642 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001643 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001644
1645 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1646 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001647 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1648 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001649 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1650
1651 ++packet_stream_it_;
1652 return packet_data;
1653 }
1654
1655 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001656 if (output_events_it_ != output_events_end_) {
1657 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001658 }
1659 }
1660
1661 bool ended() const override { return !NextEventTime(); }
1662
Danil Chapovalov431abd92018-06-18 12:54:17 +02001663 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001664 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001665 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001666 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001667 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001668 }
1669
1670 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001671 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1672 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001673 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1674 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001675 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001676};
1677
1678namespace {
1679// Creates a NetEq test object and all necessary input and output helpers. Runs
1680// the test and returns the NetEqDelayAnalyzer object that was used to
1681// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001682std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001683 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001684 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001685 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001686 const std::string& replacement_file_name,
1687 int file_sample_rate_hz) {
1688 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001689 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001690
1691 constexpr int kReplacementPt = 127;
1692 std::set<uint8_t> cn_types;
1693 std::set<uint8_t> forbidden_types;
1694 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1695 cn_types, forbidden_types));
1696
1697 NetEq::Config config;
1698 config.max_packets_in_buffer = 200;
1699 config.enable_fast_accelerate = true;
1700
1701 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1702
1703 test::NetEqTest::DecoderMap codecs;
1704
1705 // Create a "replacement decoder" that produces the decoded audio by reading
1706 // from a file rather than from the encoded payloads.
1707 std::unique_ptr<test::ResampleInputAudioFile> replacement_file(
1708 new test::ResampleInputAudioFile(replacement_file_name,
1709 file_sample_rate_hz));
1710 replacement_file->set_output_rate_hz(48000);
1711 std::unique_ptr<AudioDecoder> replacement_decoder(
1712 new test::FakeDecodeFromFile(std::move(replacement_file), 48000, false));
1713 test::NetEqTest::ExtDecoderMap ext_codecs;
1714 ext_codecs[kReplacementPt] = {replacement_decoder.get(),
1715 NetEqDecoder::kDecoderArbitrary,
1716 "replacement codec"};
1717
1718 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1719 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001720 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1721 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001722 test::DefaultNetEqTestErrorCallback error_cb;
1723 test::NetEqTest::Callbacks callbacks;
1724 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001725 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1726 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001727
1728 test::NetEqTest test(config, codecs, ext_codecs, std::move(input),
1729 std::move(output), callbacks);
1730 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001731 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001732}
1733} // namespace
1734
Minyue Lic6ff7572018-05-04 09:46:44 +02001735EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001736 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001737 int file_sample_rate_hz) const {
1738 NetEqStatsGetterMap neteq_stats;
1739
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001740 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001741 const uint32_t ssrc = stream.ssrc;
1742 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1743 continue;
1744 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1745 &stream.incoming_packets;
1746 if (audio_packets == nullptr) {
1747 // No incoming audio stream found.
1748 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001749 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001750
Minyue Li27e2b7d2018-05-07 15:20:24 +02001751 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1752
1753 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1754 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1755 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1756 // Could not find output events with SSRC matching the input audio stream.
1757 // Using the first available stream of output events.
1758 output_events_it = parsed_log_.audio_playout_events().cbegin();
1759 }
1760
Danil Chapovalov431abd92018-06-18 12:54:17 +02001761 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001762 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001763 ? absl::nullopt
1764 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001765
1766 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1767 audio_packets, &output_events_it->second, end_time_ms,
1768 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001769 }
1770
Minyue Lic6ff7572018-05-04 09:46:44 +02001771 return neteq_stats;
1772}
1773
1774// Plots the jitter buffer delay profile. This will plot only for the first
1775// incoming audio SSRC. If the stream contains more than one incoming audio
1776// SSRC, all but the first will be ignored.
1777void EventLogAnalyzer::CreateAudioJitterBufferGraph(
1778 const NetEqStatsGetterMap& neteq_stats,
1779 Plot* plot) const {
1780 if (neteq_stats.size() < 1)
1781 return;
1782
1783 const uint32_t ssrc = neteq_stats.begin()->first;
1784
henrik.lundin3c938fc2017-06-14 06:09:58 -07001785 std::vector<float> send_times_s;
1786 std::vector<float> arrival_delay_ms;
1787 std::vector<float> corrected_arrival_delay_ms;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001788 std::vector<absl::optional<float>> playout_delay_ms;
1789 std::vector<absl::optional<float>> target_delay_ms;
Minyue Lic6ff7572018-05-04 09:46:44 +02001790 neteq_stats.at(ssrc)->delay_analyzer()->CreateGraphs(
1791 &send_times_s, &arrival_delay_ms, &corrected_arrival_delay_ms,
1792 &playout_delay_ms, &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001793 RTC_DCHECK_EQ(send_times_s.size(), arrival_delay_ms.size());
1794 RTC_DCHECK_EQ(send_times_s.size(), corrected_arrival_delay_ms.size());
1795 RTC_DCHECK_EQ(send_times_s.size(), playout_delay_ms.size());
1796 RTC_DCHECK_EQ(send_times_s.size(), target_delay_ms.size());
1797
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001798 std::map<uint32_t, TimeSeries> time_series_packet_arrival;
1799 std::map<uint32_t, TimeSeries> time_series_relative_packet_arrival;
1800 std::map<uint32_t, TimeSeries> time_series_play_time;
1801 std::map<uint32_t, TimeSeries> time_series_target_time;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001802 float min_y_axis = 0.f;
1803 float max_y_axis = 0.f;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001804 for (size_t i = 0; i < send_times_s.size(); ++i) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001805 time_series_packet_arrival[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001806 TimeSeriesPoint(send_times_s[i], arrival_delay_ms[i]));
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001807 time_series_relative_packet_arrival[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001808 TimeSeriesPoint(send_times_s[i], corrected_arrival_delay_ms[i]));
1809 min_y_axis = std::min(min_y_axis, corrected_arrival_delay_ms[i]);
1810 max_y_axis = std::max(max_y_axis, corrected_arrival_delay_ms[i]);
1811 if (playout_delay_ms[i]) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001812 time_series_play_time[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001813 TimeSeriesPoint(send_times_s[i], *playout_delay_ms[i]));
1814 min_y_axis = std::min(min_y_axis, *playout_delay_ms[i]);
1815 max_y_axis = std::max(max_y_axis, *playout_delay_ms[i]);
1816 }
1817 if (target_delay_ms[i]) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001818 time_series_target_time[ssrc].points.emplace_back(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001819 TimeSeriesPoint(send_times_s[i], *target_delay_ms[i]));
1820 min_y_axis = std::min(min_y_axis, *target_delay_ms[i]);
1821 max_y_axis = std::max(max_y_axis, *target_delay_ms[i]);
1822 }
1823 }
1824
1825 // This code is adapted for a single stream. The creation of the streams above
1826 // guarantee that no more than one steam is included. If multiple streams are
1827 // to be plotted, they should likely be given distinct labels below.
1828 RTC_DCHECK_EQ(time_series_relative_packet_arrival.size(), 1);
1829 for (auto& series : time_series_relative_packet_arrival) {
1830 series.second.label = "Relative packet arrival delay";
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001831 series.second.line_style = LineStyle::kLine;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001832 plot->AppendTimeSeries(std::move(series.second));
1833 }
1834 RTC_DCHECK_EQ(time_series_play_time.size(), 1);
1835 for (auto& series : time_series_play_time) {
1836 series.second.label = "Playout delay";
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001837 series.second.line_style = LineStyle::kLine;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001838 plot->AppendTimeSeries(std::move(series.second));
1839 }
1840 RTC_DCHECK_EQ(time_series_target_time.size(), 1);
1841 for (auto& series : time_series_target_time) {
1842 series.second.label = "Target delay";
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001843 series.second.line_style = LineStyle::kLine;
1844 series.second.point_style = PointStyle::kHighlight;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001845 plot->AppendTimeSeries(std::move(series.second));
1846 }
1847
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001848 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1849 kLeftMargin, kRightMargin);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001850 plot->SetYAxis(min_y_axis, max_y_axis, "Relative delay (ms)", kBottomMargin,
1851 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001852 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
1853}
1854
1855void EventLogAnalyzer::CreateNetEqStatsGraph(
1856 const NetEqStatsGetterMap& neteq_stats,
1857 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
1858 const std::string& plot_name,
1859 Plot* plot) const {
1860 if (neteq_stats.size() < 1)
1861 return;
1862
1863 std::map<uint32_t, TimeSeries> time_series;
1864 float min_y_axis = std::numeric_limits<float>::max();
1865 float max_y_axis = std::numeric_limits<float>::min();
1866
1867 for (const auto& st : neteq_stats) {
1868 const uint32_t ssrc = st.first;
1869 const auto& stats = st.second->stats();
1870
1871 for (size_t i = 0; i < stats.size(); ++i) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001872 const float time = ToCallTimeSec(stats[i].first * 1000); // ms to us.
Minyue Li27e2b7d2018-05-07 15:20:24 +02001873 const float value = stats_extractor(stats[i].second);
1874 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
1875 min_y_axis = std::min(min_y_axis, value);
1876 max_y_axis = std::max(max_y_axis, value);
1877 }
1878 }
1879
1880 for (auto& series : time_series) {
1881 series.second.label = GetStreamName(kIncomingPacket, series.first);
1882 series.second.line_style = LineStyle::kLine;
1883 plot->AppendTimeSeries(std::move(series.second));
1884 }
1885
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001886 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1887 kLeftMargin, kRightMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001888 plot->SetYAxis(min_y_axis, max_y_axis, plot_name, kBottomMargin, kTopMargin);
1889 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001890}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001891
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001892void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1893 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001894 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001895 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1896 configs_by_cp_id.end()) {
1897 const std::string candidate_pair_desc =
1898 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001899 configs_by_cp_id[config.candidate_pair_id] =
1900 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1901 candidate_pair_desc,
1902 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001903 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1904 candidate_pair_desc;
1905 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001906 float x = ToCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001907 float y = static_cast<float>(config.type);
1908 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1909 }
1910
1911 // TODO(qingsi): There can be a large number of candidate pairs generated by
1912 // certain calls and the frontend cannot render the chart in this case due to
1913 // the failure of generating a palette with the same number of colors.
1914 for (auto& kv : configs_by_cp_id) {
1915 plot->AppendTimeSeries(std::move(kv.second));
1916 }
1917
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001918 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1919 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001920 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
1921 kTopMargin);
1922 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1923}
1924
1925std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1926 uint32_t candidate_pair_id) {
1927 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1928 candidate_pair_desc_by_id_.end()) {
1929 return candidate_pair_desc_by_id_[candidate_pair_id];
1930 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001931 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001932 // TODO(qingsi): Add the handling of the "Updated" config event after the
1933 // visualization of property change for candidate pairs is introduced.
1934 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1935 candidate_pair_desc_by_id_.end()) {
1936 const std::string candidate_pair_desc =
1937 GetCandidatePairLogDescriptionAsString(config);
1938 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1939 candidate_pair_desc;
1940 }
1941 }
1942 return candidate_pair_desc_by_id_[candidate_pair_id];
1943}
1944
1945void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1946 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001947 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001948 if (checks_by_cp_id.find(event.candidate_pair_id) ==
1949 checks_by_cp_id.end()) {
1950 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08001951 "[" + std::to_string(event.candidate_pair_id) + "]" +
1952 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001953 LineStyle::kNone, PointStyle::kHighlight);
1954 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001955 float x = ToCallTimeSec(event.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001956 float y = static_cast<float>(event.type);
1957 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1958 }
1959
1960 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1961 for (auto& kv : checks_by_cp_id) {
1962 plot->AppendTimeSeries(std::move(kv.second));
1963 }
1964
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001965 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1966 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001967 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
1968 kTopMargin);
1969 plot->SetTitle("[IceEventLog] ICE connectivity checks");
1970}
1971
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001972void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001973 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001974 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
1975 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1976 }
1977 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
1978 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1979 }
1980 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
1981 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1982 }
1983 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
1984 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1985 }
1986 for (const auto& alert : incoming_seq_num_jumps_) {
1987 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1988 }
1989 for (const auto& alert : incoming_capture_time_jumps_) {
1990 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1991 }
1992 for (const auto& alert : outgoing_seq_num_jumps_) {
1993 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1994 }
1995 for (const auto& alert : outgoing_capture_time_jumps_) {
1996 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
1997 }
1998 for (const auto& alert : outgoing_high_loss_alerts_) {
1999 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002000 }
2001 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2002}
2003
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002004void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2005 // With 100 packets/s (~800kbps), false positives would require 10 s without
2006 // data.
2007 constexpr int64_t kMaxSeqNumJump = 1000;
2008 // With a 90 kHz clock, false positives would require 10 s without data.
2009 constexpr int64_t kMaxCaptureTimeJump = 900000;
2010
2011 int64_t end_time_us = log_segments_.empty()
2012 ? std::numeric_limits<int64_t>::max()
2013 : log_segments_.front().second;
2014
2015 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002016 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002017 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002018 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002019 // Check for gaps in sequence numbers and capture timestamps.
2020 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2021 for (const auto& packet : stream.packet_view) {
2022 if (packet.log_time_us() > end_time_us) {
2023 // Only process the first (LOG_START, LOG_END) segment.
2024 break;
2025 }
2026
2027 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2028 if (last_seq_num.has_value() &&
2029 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002030 Alert_SeqNumJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002031 packet.header.ssrc);
2032 }
2033 last_seq_num.emplace(seq_num);
2034
2035 int64_t capture_time =
2036 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2037 if (last_capture_time.has_value() &&
2038 std::abs(capture_time - last_capture_time.value()) >
2039 kMaxCaptureTimeJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002040 Alert_CaptureTimeJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002041 packet.header.ssrc);
2042 }
2043 last_capture_time.emplace(capture_time);
2044 }
2045 }
2046}
2047
2048void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2049 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2050 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2051 int64_t end_time_us = log_segments_.empty()
2052 ? std::numeric_limits<int64_t>::max()
2053 : log_segments_.front().second;
2054
2055 // TODO(terelius): The parser could provide a list of all packets, ordered
2056 // by time, for each direction.
2057 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2058 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2059 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2060 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2061 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002062 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002063 for (const auto& kv : rtp_in_direction) {
2064 int64_t timestamp = kv.first;
2065 if (timestamp > end_time_us) {
2066 // Only process the first (LOG_START, LOG_END) segment.
2067 break;
2068 }
2069 int64_t duration = timestamp - last_rtp_time.value_or(0);
2070 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2071 // No packet sent/received for more than 500 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002072 Alert_RtpLogTimeGap(direction, ToCallTimeSec(timestamp), duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002073 }
2074 last_rtp_time.emplace(timestamp);
2075 }
2076
Danil Chapovalov431abd92018-06-18 12:54:17 +02002077 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002078 if (direction == kIncomingPacket) {
2079 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2080 if (rtcp.log_time_us() > end_time_us) {
2081 // Only process the first (LOG_START, LOG_END) segment.
2082 break;
2083 }
2084 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2085 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2086 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002087 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002088 duration / 1000);
2089 }
2090 last_rtcp_time.emplace(rtcp.log_time_us());
2091 }
2092 } else {
2093 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2094 if (rtcp.log_time_us() > end_time_us) {
2095 // Only process the first (LOG_START, LOG_END) segment.
2096 break;
2097 }
2098 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2099 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2100 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002101 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002102 duration / 1000);
2103 }
2104 last_rtcp_time.emplace(rtcp.log_time_us());
2105 }
2106 }
2107}
2108
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002109// TODO(terelius): Notifications could possibly be generated by the same code
2110// that produces the graphs. There is some code duplication that could be
2111// avoided, but that might be solved anyway when we move functionality from the
2112// analyzer to the parser.
2113void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002114 CreateStreamGapAlerts(kIncomingPacket);
2115 CreateStreamGapAlerts(kOutgoingPacket);
2116 CreateTransmissionGapAlerts(kIncomingPacket);
2117 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002118
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002119 int64_t end_time_us = log_segments_.empty()
2120 ? std::numeric_limits<int64_t>::max()
2121 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002122
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002123 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002124 // Loss feedback
2125 int64_t total_lost_packets = 0;
2126 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002127 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2128 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002129 // Only process the first (LOG_START, LOG_END) segment.
2130 break;
2131 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002132 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002133 bwe_update.expected_packets;
2134 total_lost_packets += lost_packets;
2135 total_expected_packets += bwe_update.expected_packets;
2136 }
2137 double avg_outgoing_loss =
2138 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002139 if (avg_outgoing_loss > kMaxLossFraction) {
2140 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002141 }
2142}
2143
terelius54ce6802016-07-13 06:44:41 -07002144} // namespace webrtc