blob: c51aae3ab5aad01286ec7c832fa0c88ebb78f845 [file] [log] [blame]
terelius54ce6802016-07-13 06:44:41 -07001/*
2 * Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020011#include "rtc_tools/event_log_visualizer/analyzer.h"
terelius54ce6802016-07-13 06:44:41 -070012
13#include <algorithm>
Oleh Prypin6581f212017-11-16 00:17:05 +010014#include <cmath>
terelius54ce6802016-07-13 06:44:41 -070015#include <limits>
16#include <map>
terelius54ce6802016-07-13 06:44:41 -070017#include <string>
18#include <utility>
19
Karl Wiberg918f50c2018-07-05 11:40:33 +020020#include "absl/memory/memory.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020021#include "call/audio_receive_stream.h"
22#include "call/audio_send_stream.h"
23#include "call/call.h"
24#include "call/video_receive_stream.h"
25#include "call/video_send_stream.h"
Mirko Bonadei71207422017-09-15 13:58:09 +020026#include "common_types.h" // NOLINT(build/include)
Elad Alon99a81b62017-09-21 10:25:29 +020027#include "logging/rtc_event_log/rtc_stream_config.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020028#include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020029#include "modules/audio_coding/neteq/tools/audio_sink.h"
30#include "modules/audio_coding/neteq/tools/fake_decode_from_file.h"
31#include "modules/audio_coding/neteq/tools/neteq_delay_analyzer.h"
32#include "modules/audio_coding/neteq/tools/neteq_replacement_input.h"
33#include "modules/audio_coding/neteq/tools/neteq_test.h"
34#include "modules/audio_coding/neteq/tools/resample_input_audio_file.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"
Sebastian Jansson04b18cb2018-07-02 09:25:25 +020037#include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
Bjorn Terelius28db2662017-10-04 14:22:43 +020038#include "modules/congestion_controller/include/receive_side_congestion_controller.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020039#include "modules/congestion_controller/include/send_side_congestion_controller.h"
40#include "modules/include/module_common_types.h"
Niels Möllerfd6c0912017-10-31 10:19:10 +010041#include "modules/pacing/packet_router.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020042#include "modules/rtp_rtcp/include/rtp_rtcp.h"
43#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020044#include "modules/rtp_rtcp/source/rtcp_packet.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020045#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
46#include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
47#include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
48#include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
49#include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
50#include "modules/rtp_rtcp/source/rtp_header_extensions.h"
51#include "modules/rtp_rtcp/source/rtp_utility.h"
52#include "rtc_base/checks.h"
53#include "rtc_base/format_macros.h"
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +020054#include "rtc_base/function_view.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020055#include "rtc_base/logging.h"
Bjorn Terelius0295a962017-10-25 17:42:41 +020056#include "rtc_base/numerics/sequence_number_util.h"
Mirko Bonadei92ea95e2017-09-15 06:47:31 +020057#include "rtc_base/rate_statistics.h"
Jonas Olsson366a50c2018-09-06 13:41:30 +020058#include "rtc_base/strings/string_builder.h"
terelius54ce6802016-07-13 06:44:41 -070059
Bjorn Terelius6984ad22017-10-24 12:19:45 +020060#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
61#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
62#endif // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
63
tereliusdc35dcd2016-08-01 12:03:27 -070064namespace webrtc {
tereliusdc35dcd2016-08-01 12:03:27 -070065
terelius54ce6802016-07-13 06:44:41 -070066namespace {
67
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080068const int kNumMicrosecsPerSec = 1000000;
69
elad.alonec304f92017-03-08 05:03:53 -080070void SortPacketFeedbackVector(std::vector<PacketFeedback>* vec) {
71 auto pred = [](const PacketFeedback& packet_feedback) {
72 return packet_feedback.arrival_time_ms == PacketFeedback::kNotReceived;
73 };
74 vec->erase(std::remove_if(vec->begin(), vec->end(), pred), vec->end());
75 std::sort(vec->begin(), vec->end(), PacketFeedbackComparator());
76}
77
terelius54ce6802016-07-13 06:44:41 -070078std::string SsrcToString(uint32_t ssrc) {
Jonas Olsson366a50c2018-09-06 13:41:30 +020079 rtc::StringBuilder ss;
terelius54ce6802016-07-13 06:44:41 -070080 ss << "SSRC " << ssrc;
81 return ss.str();
82}
83
84// Checks whether an SSRC is contained in the list of desired SSRCs.
85// Note that an empty SSRC list matches every SSRC.
86bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
87 if (desired_ssrc.size() == 0)
88 return true;
89 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
90 desired_ssrc.end();
91}
92
93double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
94 // The timestamp is a fixed point representation with 6 bits for seconds
95 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080096 // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
97 // microseconds.
terelius54ce6802016-07-13 06:44:41 -070098 static constexpr double kTimestampToMicroSec =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -080099 static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
terelius54ce6802016-07-13 06:44:41 -0700100 return abs_send_time * kTimestampToMicroSec;
101}
102
103// Computes the difference |later| - |earlier| where |later| and |earlier|
104// are counters that wrap at |modulus|. The difference is chosen to have the
105// least absolute value. For example if |modulus| is 8, then the difference will
106// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
107// be in [-4, 4].
108int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
109 RTC_DCHECK_LE(1, modulus);
110 RTC_DCHECK_LT(later, modulus);
111 RTC_DCHECK_LT(earlier, modulus);
112 int64_t difference =
113 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
114 int64_t max_difference = modulus / 2;
115 int64_t min_difference = max_difference - modulus + 1;
116 if (difference > max_difference) {
117 difference -= modulus;
118 }
119 if (difference < min_difference) {
120 difference += modulus;
121 }
terelius6addf492016-08-23 17:34:07 -0700122 if (difference > max_difference / 2 || difference < min_difference / 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100123 RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
124 << " expected to be in the range ("
125 << min_difference / 2 << "," << max_difference / 2
126 << ") but is " << difference
127 << ". Correct unwrapping is uncertain.";
terelius6addf492016-08-23 17:34:07 -0700128 }
terelius54ce6802016-07-13 06:44:41 -0700129 return difference;
130}
131
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200132// This is much more reliable for outgoing streams than for incoming streams.
133template <typename RtpPacketContainer>
Danil Chapovalov431abd92018-06-18 12:54:17 +0200134absl::optional<uint32_t> EstimateRtpClockFrequency(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200135 const RtpPacketContainer& packets,
136 int64_t end_time_us) {
137 RTC_CHECK(packets.size() >= 2);
138 SeqNumUnwrapper<uint32_t> unwrapper;
139 uint64_t first_rtp_timestamp =
140 unwrapper.Unwrap(packets[0].rtp.header.timestamp);
141 int64_t first_log_timestamp = packets[0].log_time_us();
142 uint64_t last_rtp_timestamp = first_rtp_timestamp;
143 int64_t last_log_timestamp = first_log_timestamp;
144 for (size_t i = 1; i < packets.size(); i++) {
145 if (packets[i].log_time_us() > end_time_us)
146 break;
147 last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
148 last_log_timestamp = packets[i].log_time_us();
149 }
150 if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
151 RTC_LOG(LS_WARNING)
152 << "Failed to estimate RTP clock frequency: Stream too short. ("
153 << packets.size() << " packets, "
154 << last_log_timestamp - first_log_timestamp << " us)";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200155 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200156 }
157 double duration =
158 static_cast<double>(last_log_timestamp - first_log_timestamp) /
159 kNumMicrosecsPerSec;
160 double estimated_frequency =
161 (last_rtp_timestamp - first_rtp_timestamp) / duration;
162 for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
163 if (std::fabs(estimated_frequency - f) < 0.05 * f) {
164 return f;
165 }
166 }
167 RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
168 << estimated_frequency
169 << "not close to any stardard RTP frequency.";
Danil Chapovalov431abd92018-06-18 12:54:17 +0200170 return absl::nullopt;
ivocaac9d6f2016-09-22 07:01:47 -0700171}
172
tereliusdc35dcd2016-08-01 12:03:27 -0700173constexpr float kLeftMargin = 0.01f;
174constexpr float kRightMargin = 0.02f;
175constexpr float kBottomMargin = 0.02f;
176constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700177
Danil Chapovalov431abd92018-06-18 12:54:17 +0200178absl::optional<double> NetworkDelayDiff_AbsSendTime(
terelius53dc23c2017-03-13 05:24:05 -0700179 const LoggedRtpPacket& old_packet,
180 const LoggedRtpPacket& new_packet) {
181 if (old_packet.header.extension.hasAbsoluteSendTime &&
182 new_packet.header.extension.hasAbsoluteSendTime) {
183 int64_t send_time_diff = WrappingDifference(
184 new_packet.header.extension.absoluteSendTime,
185 old_packet.header.extension.absoluteSendTime, 1ul << 24);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200186 int64_t recv_time_diff =
187 new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700188 double delay_change_us =
189 recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100190 return delay_change_us / 1000;
terelius53dc23c2017-03-13 05:24:05 -0700191 } else {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200192 return absl::nullopt;
terelius6addf492016-08-23 17:34:07 -0700193 }
194}
195
Danil Chapovalov431abd92018-06-18 12:54:17 +0200196absl::optional<double> NetworkDelayDiff_CaptureTime(
terelius53dc23c2017-03-13 05:24:05 -0700197 const LoggedRtpPacket& old_packet,
198 const LoggedRtpPacket& new_packet) {
199 int64_t send_time_diff = WrappingDifference(
200 new_packet.header.timestamp, old_packet.header.timestamp, 1ull << 32);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200201 int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
terelius53dc23c2017-03-13 05:24:05 -0700202
203 const double kVideoSampleRate = 90000;
204 // TODO(terelius): We treat all streams as video for now, even though
205 // audio might be sampled at e.g. 16kHz, because it is really difficult to
206 // figure out the true sampling rate of a stream. The effect is that the
207 // delay will be scaled incorrectly for non-video streams.
208
209 double delay_change =
210 static_cast<double>(recv_time_diff) / 1000 -
211 static_cast<double>(send_time_diff) / kVideoSampleRate * 1000;
212 if (delay_change < -10000 || 10000 < delay_change) {
Mirko Bonadei675513b2017-11-09 11:09:25 +0100213 RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
214 RTC_LOG(LS_WARNING) << "Old capture time " << old_packet.header.timestamp
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200215 << ", received time " << old_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100216 RTC_LOG(LS_WARNING) << "New capture time " << new_packet.header.timestamp
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200217 << ", received time " << new_packet.log_time_us();
Mirko Bonadei675513b2017-11-09 11:09:25 +0100218 RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800219 << static_cast<double>(recv_time_diff) /
220 kNumMicrosecsPerSec
221 << "s";
Mirko Bonadei675513b2017-11-09 11:09:25 +0100222 RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
223 << static_cast<double>(send_time_diff) /
224 kVideoSampleRate
225 << "s";
terelius53dc23c2017-03-13 05:24:05 -0700226 }
Oskar Sundbom3928dbc2017-11-16 10:53:09 +0100227 return delay_change;
terelius53dc23c2017-03-13 05:24:05 -0700228}
229
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200230// For each element in data_view, use |f()| to extract a y-coordinate and
terelius53dc23c2017-03-13 05:24:05 -0700231// store the result in a TimeSeries.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200232template <typename DataType, typename IterableType>
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200233void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200234 rtc::FunctionView<absl::optional<float>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200235 const IterableType& data_view,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200236 TimeSeries* result) {
237 for (size_t i = 0; i < data_view.size(); i++) {
238 const DataType& elem = data_view[i];
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200239 float x = fx(elem);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200240 absl::optional<float> y = fy(elem);
terelius53dc23c2017-03-13 05:24:05 -0700241 if (y)
242 result->points.emplace_back(x, *y);
243 }
244}
245
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200246// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius6addf492016-08-23 17:34:07 -0700247// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
248// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200249template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700250void ProcessPairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200251 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200252 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
253 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200254 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700255 TimeSeries* result) {
tereliusccbbf8d2016-08-10 07:34:28 -0700256 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200257 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200258 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700259 if (y)
260 result->points.emplace_back(x, static_cast<float>(*y));
261 }
262}
263
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200264// For each pair of adjacent elements in |data|, use |f()| to extract a
terelius53dc23c2017-03-13 05:24:05 -0700265// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
266// will be the time of the second element in the pair.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200267template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700268void AccumulatePairs(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200269 rtc::FunctionView<float(const DataType&)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200270 rtc::FunctionView<absl::optional<ResultType>(const DataType&,
271 const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200272 const IterableType& data,
terelius53dc23c2017-03-13 05:24:05 -0700273 TimeSeries* result) {
274 ResultType sum = 0;
275 for (size_t i = 1; i < data.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200276 float x = fx(data[i]);
Danil Chapovalov431abd92018-06-18 12:54:17 +0200277 absl::optional<ResultType> y = fy(data[i - 1], data[i]);
terelius53dc23c2017-03-13 05:24:05 -0700278 if (y)
279 sum += *y;
280 result->points.emplace_back(x, static_cast<float>(sum));
tereliusccbbf8d2016-08-10 07:34:28 -0700281 }
282}
283
terelius6addf492016-08-23 17:34:07 -0700284// Calculates a moving average of |data| and stores the result in a TimeSeries.
285// A data point is generated every |step| microseconds from |begin_time|
286// to |end_time|. The value of each data point is the average of the data
287// during the preceeding |window_duration_us| microseconds.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200288template <typename DataType, typename ResultType, typename IterableType>
terelius53dc23c2017-03-13 05:24:05 -0700289void MovingAverage(
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200290 rtc::FunctionView<float(int64_t)> fx,
Danil Chapovalov431abd92018-06-18 12:54:17 +0200291 rtc::FunctionView<absl::optional<ResultType>(const DataType&)> fy,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200292 const IterableType& data_view,
293 int64_t begin_time,
294 int64_t end_time,
295 int64_t window_duration_us,
296 int64_t step,
297 TimeSeries* result) {
terelius6addf492016-08-23 17:34:07 -0700298 size_t window_index_begin = 0;
299 size_t window_index_end = 0;
terelius53dc23c2017-03-13 05:24:05 -0700300 ResultType sum_in_window = 0;
terelius6addf492016-08-23 17:34:07 -0700301
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200302 for (int64_t t = begin_time; t < end_time + step; t += step) {
303 while (window_index_end < data_view.size() &&
304 data_view[window_index_end].log_time_us() < t) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200305 absl::optional<ResultType> value = fy(data_view[window_index_end]);
terelius53dc23c2017-03-13 05:24:05 -0700306 if (value)
307 sum_in_window += *value;
terelius6addf492016-08-23 17:34:07 -0700308 ++window_index_end;
309 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200310 while (window_index_begin < data_view.size() &&
311 data_view[window_index_begin].log_time_us() <
312 t - window_duration_us) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200313 absl::optional<ResultType> value = fy(data_view[window_index_begin]);
terelius53dc23c2017-03-13 05:24:05 -0700314 if (value)
315 sum_in_window -= *value;
terelius6addf492016-08-23 17:34:07 -0700316 ++window_index_begin;
317 }
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800318 float window_duration_s =
319 static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200320 float x = fx(t);
terelius53dc23c2017-03-13 05:24:05 -0700321 float y = sum_in_window / window_duration_s;
terelius6addf492016-08-23 17:34:07 -0700322 result->points.emplace_back(x, y);
323 }
324}
325
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800326const char kUnknownEnumValue[] = "unknown";
327
328const char kIceCandidateTypeLocal[] = "local";
329const char kIceCandidateTypeStun[] = "stun";
330const char kIceCandidateTypePrflx[] = "prflx";
331const char kIceCandidateTypeRelay[] = "relay";
332
333const char kProtocolUdp[] = "udp";
334const char kProtocolTcp[] = "tcp";
335const char kProtocolSsltcp[] = "ssltcp";
336const char kProtocolTls[] = "tls";
337
338const char kAddressFamilyIpv4[] = "ipv4";
339const char kAddressFamilyIpv6[] = "ipv6";
340
341const char kNetworkTypeEthernet[] = "ethernet";
342const char kNetworkTypeLoopback[] = "loopback";
343const char kNetworkTypeWifi[] = "wifi";
344const char kNetworkTypeVpn[] = "vpn";
345const char kNetworkTypeCellular[] = "cellular";
346
347std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
348 switch (type) {
349 case webrtc::IceCandidateType::kLocal:
350 return kIceCandidateTypeLocal;
351 case webrtc::IceCandidateType::kStun:
352 return kIceCandidateTypeStun;
353 case webrtc::IceCandidateType::kPrflx:
354 return kIceCandidateTypePrflx;
355 case webrtc::IceCandidateType::kRelay:
356 return kIceCandidateTypeRelay;
357 default:
358 return kUnknownEnumValue;
359 }
360}
361
362std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
363 switch (protocol) {
364 case webrtc::IceCandidatePairProtocol::kUdp:
365 return kProtocolUdp;
366 case webrtc::IceCandidatePairProtocol::kTcp:
367 return kProtocolTcp;
368 case webrtc::IceCandidatePairProtocol::kSsltcp:
369 return kProtocolSsltcp;
370 case webrtc::IceCandidatePairProtocol::kTls:
371 return kProtocolTls;
372 default:
373 return kUnknownEnumValue;
374 }
375}
376
377std::string GetAddressFamilyAsString(
378 webrtc::IceCandidatePairAddressFamily family) {
379 switch (family) {
380 case webrtc::IceCandidatePairAddressFamily::kIpv4:
381 return kAddressFamilyIpv4;
382 case webrtc::IceCandidatePairAddressFamily::kIpv6:
383 return kAddressFamilyIpv6;
384 default:
385 return kUnknownEnumValue;
386 }
387}
388
389std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
390 switch (type) {
391 case webrtc::IceCandidateNetworkType::kEthernet:
392 return kNetworkTypeEthernet;
393 case webrtc::IceCandidateNetworkType::kLoopback:
394 return kNetworkTypeLoopback;
395 case webrtc::IceCandidateNetworkType::kWifi:
396 return kNetworkTypeWifi;
397 case webrtc::IceCandidateNetworkType::kVpn:
398 return kNetworkTypeVpn;
399 case webrtc::IceCandidateNetworkType::kCellular:
400 return kNetworkTypeCellular;
401 default:
402 return kUnknownEnumValue;
403 }
404}
405
406std::string GetCandidatePairLogDescriptionAsString(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200407 const LoggedIceCandidatePairConfig& config) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800408 // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
409 // represents a pair of a local server-reflexive candidate on a WiFi network
410 // and a remote relay candidate using TCP as the relay protocol on a cell
411 // network, when the candidate pair communicates over UDP using IPv4.
Jonas Olsson366a50c2018-09-06 13:41:30 +0200412 rtc::StringBuilder ss;
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800413 std::string local_candidate_type =
414 GetIceCandidateTypeAsString(config.local_candidate_type);
415 std::string remote_candidate_type =
416 GetIceCandidateTypeAsString(config.remote_candidate_type);
417 if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
418 local_candidate_type +=
419 "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
420 }
421 ss << local_candidate_type << ":"
422 << GetNetworkTypeAsString(config.local_network_type) << ":"
423 << GetAddressFamilyAsString(config.local_address_family) << "->"
424 << remote_candidate_type << ":"
425 << GetAddressFamilyAsString(config.remote_address_family) << "@"
426 << GetProtocolAsString(config.candidate_pair_protocol);
427 return ss.str();
428}
429
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200430std::string GetDirectionAsString(PacketDirection direction) {
431 if (direction == kIncomingPacket) {
432 return "Incoming";
433 } else {
434 return "Outgoing";
435 }
436}
437
438std::string GetDirectionAsShortString(PacketDirection direction) {
439 if (direction == kIncomingPacket) {
440 return "In";
441 } else {
442 return "Out";
443 }
444}
445
terelius54ce6802016-07-13 06:44:41 -0700446} // namespace
447
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200448EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log,
449 bool normalize_time)
450 : parsed_log_(log),
451 window_duration_(250000),
452 step_(10000),
453 normalize_time_(normalize_time) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200454 begin_time_ = parsed_log_.first_timestamp();
455 end_time_ = parsed_log_.last_timestamp();
456 if (end_time_ < begin_time_) {
457 RTC_LOG(LS_WARNING) << "No useful events in the log.";
458 begin_time_ = end_time_ = 0;
Björn Tereliusff612732018-04-25 14:23:01 +0000459 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200460 call_duration_s_ = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200461
462 const auto& log_start_events = parsed_log_.start_log_events();
463 const auto& log_end_events = parsed_log_.stop_log_events();
464 auto start_iter = log_start_events.begin();
465 auto end_iter = log_end_events.begin();
466 while (start_iter != log_start_events.end()) {
467 int64_t start = start_iter->log_time_us();
468 ++start_iter;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200469 absl::optional<int64_t> next_start;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200470 if (start_iter != log_start_events.end())
471 next_start.emplace(start_iter->log_time_us());
472 if (end_iter != log_end_events.end() &&
473 end_iter->log_time_us() <=
474 next_start.value_or(std::numeric_limits<int64_t>::max())) {
475 int64_t end = end_iter->log_time_us();
476 RTC_DCHECK_LE(start, end);
477 log_segments_.push_back(std::make_pair(start, end));
478 ++end_iter;
479 } else {
480 // we're missing an end event. Assume that it occurred just before the
481 // next start.
482 log_segments_.push_back(
483 std::make_pair(start, next_start.value_or(end_time_)));
484 }
henrik.lundin3c938fc2017-06-14 06:09:58 -0700485 }
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100486 RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
Yves Gerey665174f2018-06-19 15:03:05 +0200487 << " (LOG_START, LOG_END) segments in log.";
terelius54ce6802016-07-13 06:44:41 -0700488}
489
Sebastian Janssone4be6da2018-02-15 16:51:41 +0100490class BitrateObserver : public NetworkChangedObserver,
Stefan Holmer13181032016-07-29 14:48:54 +0200491 public RemoteBitrateObserver {
492 public:
493 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
494
495 void OnNetworkChanged(uint32_t bitrate_bps,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200496 uint8_t fraction_lost,
minyue78b4d562016-11-30 04:47:39 -0800497 int64_t rtt_ms,
498 int64_t probing_interval_ms) override {
Stefan Holmer13181032016-07-29 14:48:54 +0200499 last_bitrate_bps_ = bitrate_bps;
500 bitrate_updated_ = true;
501 }
502
503 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
504 uint32_t bitrate) override {}
505
506 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
507 bool GetAndResetBitrateUpdated() {
508 bool bitrate_updated = bitrate_updated_;
509 bitrate_updated_ = false;
510 return bitrate_updated;
511 }
512
513 private:
514 uint32_t last_bitrate_bps_;
515 bool bitrate_updated_;
516};
517
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200518int64_t EventLogAnalyzer::ToCallTimeUs(int64_t timestamp) const {
519 int64_t begin_time = 0;
520 if (normalize_time_) {
521 begin_time = begin_time_;
522 }
523 return timestamp - begin_time;
524}
525
526float EventLogAnalyzer::ToCallTimeSec(int64_t timestamp) const {
527 return static_cast<float>(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100528}
529
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200530void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
terelius54ce6802016-07-13 06:44:41 -0700531 Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200532 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
533 // Filter on SSRC.
534 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700535 continue;
terelius54ce6802016-07-13 06:44:41 -0700536 }
terelius54ce6802016-07-13 06:44:41 -0700537
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200538 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
539 LineStyle::kBar);
540 auto GetPacketSize = [](const LoggedRtpPacket& packet) {
Danil Chapovalov431abd92018-06-18 12:54:17 +0200541 return absl::optional<float>(packet.total_length);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200542 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200543 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
544 return this->ToCallTimeSec(packet.log_time_us());
545 };
546 ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
547 stream.packet_view, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700548 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700549 }
550
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200551 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
552 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700553 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
554 kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200555 plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700556}
557
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200558template <typename IterableType>
philipelccd74892016-09-05 02:46:25 -0700559void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
philipelccd74892016-09-05 02:46:25 -0700560 Plot* plot,
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200561 const IterableType& packets,
562 const std::string& label) {
563 TimeSeries time_series(label, LineStyle::kStep);
564 for (size_t i = 0; i < packets.size(); i++) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200565 float x = ToCallTimeSec(packets[i].log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200566 time_series.points.emplace_back(x, i + 1);
philipelccd74892016-09-05 02:46:25 -0700567 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200568 plot->AppendTimeSeries(std::move(time_series));
philipelccd74892016-09-05 02:46:25 -0700569}
570
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200571void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
572 Plot* plot) {
573 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
574 if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
575 continue;
576 std::string label =
577 std::string("RTP ") + GetStreamName(direction, stream.ssrc);
578 CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
579 }
580 std::string label =
581 std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
582 if (direction == kIncomingPacket) {
583 CreateAccumulatedPacketsTimeSeries(
584 plot, parsed_log_.incoming_rtcp_packets(), label);
585 } else {
586 CreateAccumulatedPacketsTimeSeries(
587 plot, parsed_log_.outgoing_rtcp_packets(), label);
588 }
philipelccd74892016-09-05 02:46:25 -0700589
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200590 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
591 kLeftMargin, kRightMargin);
philipelccd74892016-09-05 02:46:25 -0700592 plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200593 plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
594 " RTP/RTCP packets");
philipelccd74892016-09-05 02:46:25 -0700595}
596
terelius54ce6802016-07-13 06:44:41 -0700597// For each SSRC, plot the time between the consecutive playouts.
598void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200599 for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
600 uint32_t ssrc = playout_stream.first;
601 if (!MatchingSsrc(ssrc, desired_ssrc_))
602 continue;
Danil Chapovalov431abd92018-06-18 12:54:17 +0200603 absl::optional<int64_t> last_playout_ms;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200604 TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
Minyue Li27e2b7d2018-05-07 15:20:24 +0200605 for (const auto& playout_event : playout_stream.second) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200606 float x = ToCallTimeSec(playout_event.log_time_us());
Minyue Li27e2b7d2018-05-07 15:20:24 +0200607 int64_t playout_time_ms = playout_event.log_time_ms();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200608 // If there were no previous playouts, place the point on the x-axis.
Minyue Li27e2b7d2018-05-07 15:20:24 +0200609 float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200610 time_series.points.push_back(TimeSeriesPoint(x, y));
Minyue Li27e2b7d2018-05-07 15:20:24 +0200611 last_playout_ms.emplace(playout_time_ms);
terelius54ce6802016-07-13 06:44:41 -0700612 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200613 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700614 }
615
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200616 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
617 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700618 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
619 kTopMargin);
620 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700621}
622
ivocaac9d6f2016-09-22 07:01:47 -0700623// For audio SSRCs, plot the audio level.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200624void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
625 Plot* plot) {
626 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
627 if (!IsAudioSsrc(direction, stream.ssrc))
628 continue;
629 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
630 LineStyle::kLine);
631 for (auto& packet : stream.packet_view) {
ivocaac9d6f2016-09-22 07:01:47 -0700632 if (packet.header.extension.hasAudioLevel) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200633 float x = ToCallTimeSec(packet.log_time_us());
ivocaac9d6f2016-09-22 07:01:47 -0700634 // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
635 // Here we convert it to dBov.
636 float y = static_cast<float>(-packet.header.extension.audioLevel);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200637 time_series.points.emplace_back(TimeSeriesPoint(x, y));
ivocaac9d6f2016-09-22 07:01:47 -0700638 }
639 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200640 plot->AppendTimeSeries(std::move(time_series));
ivocaac9d6f2016-09-22 07:01:47 -0700641 }
642
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200643 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
644 kLeftMargin, kRightMargin);
Yves Gerey665174f2018-06-19 15:03:05 +0200645 plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200646 plot->SetTitle(GetDirectionAsString(direction) + " audio level");
ivocaac9d6f2016-09-22 07:01:47 -0700647}
648
terelius54ce6802016-07-13 06:44:41 -0700649// For each SSRC, plot the time between the consecutive playouts.
650void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200651 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
652 // Filter on SSRC.
653 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -0700654 continue;
terelius54ce6802016-07-13 06:44:41 -0700655 }
terelius54ce6802016-07-13 06:44:41 -0700656
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200657 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
658 LineStyle::kBar);
659 auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
660 const LoggedRtpPacketIncoming& new_packet) {
661 int64_t diff =
662 WrappingDifference(new_packet.rtp.header.sequenceNumber,
663 old_packet.rtp.header.sequenceNumber, 1ul << 16);
664 return diff;
665 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200666 auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
667 return this->ToCallTimeSec(packet.log_time_us());
668 };
669 ProcessPairs<LoggedRtpPacketIncoming, float>(
670 ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
671 &time_series);
philipel35ba9bd2017-04-19 05:58:51 -0700672 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700673 }
674
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200675 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
676 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700677 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
678 kTopMargin);
679 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700680}
681
Stefan Holmer99f8e082016-09-09 13:37:50 +0200682void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200683 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
684 const std::vector<LoggedRtpPacketIncoming>& packets =
685 stream.incoming_packets;
686 // Filter on SSRC.
687 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.size() == 0) {
Stefan Holmer99f8e082016-09-09 13:37:50 +0200688 continue;
689 }
690
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200691 TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc),
692 LineStyle::kLine, PointStyle::kHighlight);
693 // TODO(terelius): Should the window and step size be read from the class
694 // instead?
695 const int64_t kWindowUs = 1000000;
696 const int64_t kStep = 1000000;
Bjorn Terelius2eb31882017-11-30 15:15:25 +0100697 SeqNumUnwrapper<uint16_t> unwrapper_;
698 SeqNumUnwrapper<uint16_t> prior_unwrapper_;
terelius4c9b4af2017-01-30 08:44:51 -0800699 size_t window_index_begin = 0;
700 size_t window_index_end = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200701 uint64_t highest_seq_number =
702 unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
703 uint64_t highest_prior_seq_number =
704 prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
terelius4c9b4af2017-01-30 08:44:51 -0800705
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200706 for (int64_t t = begin_time_; t < end_time_ + kStep; t += kStep) {
707 while (window_index_end < packets.size() &&
708 packets[window_index_end].rtp.log_time_us() < t) {
709 uint64_t sequence_number = unwrapper_.Unwrap(
710 packets[window_index_end].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800711 highest_seq_number = std::max(highest_seq_number, sequence_number);
712 ++window_index_end;
Stefan Holmer99f8e082016-09-09 13:37:50 +0200713 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200714 while (window_index_begin < packets.size() &&
715 packets[window_index_begin].rtp.log_time_us() < t - kWindowUs) {
716 uint64_t sequence_number = prior_unwrapper_.Unwrap(
717 packets[window_index_begin].rtp.header.sequenceNumber);
terelius4c9b4af2017-01-30 08:44:51 -0800718 highest_prior_seq_number =
719 std::max(highest_prior_seq_number, sequence_number);
720 ++window_index_begin;
721 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200722 float x = ToCallTimeSec(t);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200723 uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
terelius4c9b4af2017-01-30 08:44:51 -0800724 if (expected_packets > 0) {
725 int64_t received_packets = window_index_end - window_index_begin;
726 int64_t lost_packets = expected_packets - received_packets;
727 float y = static_cast<float>(lost_packets) / expected_packets * 100;
728 time_series.points.emplace_back(x, y);
729 }
Stefan Holmer99f8e082016-09-09 13:37:50 +0200730 }
philipel35ba9bd2017-04-19 05:58:51 -0700731 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer99f8e082016-09-09 13:37:50 +0200732 }
733
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200734 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
735 kLeftMargin, kRightMargin);
Stefan Holmer99f8e082016-09-09 13:37:50 +0200736 plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
737 kTopMargin);
738 plot->SetTitle("Estimated incoming loss rate");
739}
740
terelius2ee076d2017-08-15 02:04:02 -0700741void EventLogAnalyzer::CreateIncomingDelayDeltaGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200742 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(kIncomingPacket)) {
743 // Filter on SSRC.
744 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
745 IsAudioSsrc(kIncomingPacket, stream.ssrc) ||
746 !IsVideoSsrc(kIncomingPacket, stream.ssrc) ||
747 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700748 continue;
749 }
terelius54ce6802016-07-13 06:44:41 -0700750
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200751 TimeSeries capture_time_data(
752 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
753 LineStyle::kBar);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200754 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
755 return this->ToCallTimeSec(packet.log_time_us());
756 };
757 ProcessPairs<LoggedRtpPacket, double>(
758 ToCallTime, NetworkDelayDiff_CaptureTime, stream.packet_view,
759 &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700760 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700761
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200762 TimeSeries send_time_data(
763 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
764 LineStyle::kBar);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200765 ProcessPairs<LoggedRtpPacket, double>(ToCallTime,
766 NetworkDelayDiff_AbsSendTime,
767 stream.packet_view, &send_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700768 plot->AppendTimeSeries(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700769 }
770
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200771 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
772 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700773 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
774 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700775 plot->SetTitle("Network latency difference between consecutive packets");
terelius54ce6802016-07-13 06:44:41 -0700776}
777
terelius2ee076d2017-08-15 02:04:02 -0700778void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200779 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(kIncomingPacket)) {
780 // Filter on SSRC.
781 if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
782 IsAudioSsrc(kIncomingPacket, stream.ssrc) ||
783 !IsVideoSsrc(kIncomingPacket, stream.ssrc) ||
784 IsRtxSsrc(kIncomingPacket, stream.ssrc)) {
terelius88e64e52016-07-19 01:51:06 -0700785 continue;
786 }
terelius54ce6802016-07-13 06:44:41 -0700787
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200788 TimeSeries capture_time_data(
789 GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
790 LineStyle::kLine);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200791 auto ToCallTime = [this](const LoggedRtpPacket& packet) {
792 return this->ToCallTimeSec(packet.log_time_us());
793 };
794 AccumulatePairs<LoggedRtpPacket, double>(
795 ToCallTime, NetworkDelayDiff_CaptureTime, stream.packet_view,
796 &capture_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700797 plot->AppendTimeSeries(std::move(capture_time_data));
terelius88e64e52016-07-19 01:51:06 -0700798
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200799 TimeSeries send_time_data(
800 GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
801 LineStyle::kLine);
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200802 AccumulatePairs<LoggedRtpPacket, double>(
803 ToCallTime, NetworkDelayDiff_AbsSendTime, stream.packet_view,
804 &send_time_data);
philipel35ba9bd2017-04-19 05:58:51 -0700805 plot->AppendTimeSeries(std::move(send_time_data));
terelius54ce6802016-07-13 06:44:41 -0700806 }
807
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200808 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
809 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -0700810 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
811 kTopMargin);
terelius2ee076d2017-08-15 02:04:02 -0700812 plot->SetTitle("Network latency (relative to first packet)");
terelius54ce6802016-07-13 06:44:41 -0700813}
814
tereliusf736d232016-08-04 10:00:11 -0700815// Plot the fraction of packets lost (as perceived by the loss-based BWE).
816void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100817 TimeSeries time_series("Fraction lost", LineStyle::kLine,
818 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200819 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200820 float x = ToCallTimeSec(bwe_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200821 float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
philipel35ba9bd2017-04-19 05:58:51 -0700822 time_series.points.emplace_back(x, y);
tereliusf736d232016-08-04 10:00:11 -0700823 }
tereliusf736d232016-08-04 10:00:11 -0700824
Bjorn Terelius19f5be32017-10-18 12:39:49 +0200825 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200826 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
827 kLeftMargin, kRightMargin);
tereliusf736d232016-08-04 10:00:11 -0700828 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
829 kTopMargin);
830 plot->SetTitle("Reported packet loss");
831}
832
terelius54ce6802016-07-13 06:44:41 -0700833// Plot the total bandwidth used by all RTP streams.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200834void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
835 // TODO(terelius): This could be provided by the parser.
836 std::multimap<int64_t, size_t> packets_in_order;
837 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
838 for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
839 packets_in_order.insert(
840 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
terelius54ce6802016-07-13 06:44:41 -0700841 }
842
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200843 auto window_begin = packets_in_order.begin();
844 auto window_end = packets_in_order.begin();
terelius54ce6802016-07-13 06:44:41 -0700845 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700846
847 // Calculate a moving average of the bitrate and store in a TimeSeries.
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +0100848 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200849 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
850 while (window_end != packets_in_order.end() && window_end->first < time) {
851 bytes_in_window += window_end->second;
852 ++window_end;
terelius54ce6802016-07-13 06:44:41 -0700853 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200854 while (window_begin != packets_in_order.end() &&
855 window_begin->first < time - window_duration_) {
856 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
857 bytes_in_window -= window_begin->second;
858 ++window_begin;
859 }
860 float window_duration_in_seconds =
861 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200862 float x = ToCallTimeSec(time);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200863 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
864 bitrate_series.points.emplace_back(x, y);
865 }
866 plot->AppendTimeSeries(std::move(bitrate_series));
867
868 // Overlay the outgoing REMB over incoming bitrate.
869 TimeSeries remb_series("Remb", LineStyle::kStep);
870 for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200871 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200872 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
873 remb_series.points.emplace_back(x, y);
874 }
875 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
876
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200877 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
878 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200879 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
880 plot->SetTitle("Incoming RTP bitrate");
881}
882
883// Plot the total bandwidth used by all RTP streams.
884void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot,
885 bool show_detector_state,
886 bool show_alr_state) {
887 // TODO(terelius): This could be provided by the parser.
888 std::multimap<int64_t, size_t> packets_in_order;
889 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
890 for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
891 packets_in_order.insert(
892 std::make_pair(packet.rtp.log_time_us(), packet.rtp.total_length));
893 }
894
895 auto window_begin = packets_in_order.begin();
896 auto window_end = packets_in_order.begin();
897 size_t bytes_in_window = 0;
898
899 // Calculate a moving average of the bitrate and store in a TimeSeries.
900 TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
901 for (int64_t time = begin_time_; time < end_time_ + step_; time += step_) {
902 while (window_end != packets_in_order.end() && window_end->first < time) {
903 bytes_in_window += window_end->second;
904 ++window_end;
905 }
906 while (window_begin != packets_in_order.end() &&
907 window_begin->first < time - window_duration_) {
908 RTC_DCHECK_LE(window_begin->second, bytes_in_window);
909 bytes_in_window -= window_begin->second;
910 ++window_begin;
terelius54ce6802016-07-13 06:44:41 -0700911 }
912 float window_duration_in_seconds =
Qingsi Wang8eca1ff2018-02-02 11:49:44 -0800913 static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200914 float x = ToCallTimeSec(time);
terelius54ce6802016-07-13 06:44:41 -0700915 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
philipel35ba9bd2017-04-19 05:58:51 -0700916 bitrate_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700917 }
philipel35ba9bd2017-04-19 05:58:51 -0700918 plot->AppendTimeSeries(std::move(bitrate_series));
terelius54ce6802016-07-13 06:44:41 -0700919
terelius8058e582016-07-25 01:32:41 -0700920 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200921 TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
922 for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200923 float x = ToCallTimeSec(loss_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200924 float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
925 loss_series.points.emplace_back(x, y);
926 }
philipel10fc0e62017-04-11 01:50:23 -0700927
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200928 TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
929 IntervalSeries overusing_series("Overusing", "#ff8e82",
930 IntervalSeries::kHorizontal);
931 IntervalSeries underusing_series("Underusing", "#5092fc",
932 IntervalSeries::kHorizontal);
933 IntervalSeries normal_series("Normal", "#c4ffc4",
934 IntervalSeries::kHorizontal);
935 IntervalSeries* last_series = &normal_series;
936 double last_detector_switch = 0.0;
philipel23c7f252017-07-14 06:30:03 -0700937
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200938 BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
philipel23c7f252017-07-14 06:30:03 -0700939
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200940 for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200941 float x = ToCallTimeSec(delay_update.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200942 float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
philipel23c7f252017-07-14 06:30:03 -0700943
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200944 if (last_detector_state != delay_update.detector_state) {
945 last_series->intervals.emplace_back(last_detector_switch, x);
946 last_detector_state = delay_update.detector_state;
947 last_detector_switch = x;
philipel23c7f252017-07-14 06:30:03 -0700948
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200949 switch (delay_update.detector_state) {
950 case BandwidthUsage::kBwNormal:
951 last_series = &normal_series;
952 break;
953 case BandwidthUsage::kBwUnderusing:
954 last_series = &underusing_series;
955 break;
956 case BandwidthUsage::kBwOverusing:
957 last_series = &overusing_series;
958 break;
959 case BandwidthUsage::kLast:
960 RTC_NOTREACHED();
philipele127e7a2017-03-29 16:28:53 +0200961 }
962 }
philipel23c7f252017-07-14 06:30:03 -0700963
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200964 delay_series.points.emplace_back(x, y);
965 }
Bjorn Terelius9e336ec2018-04-24 16:28:35 +0200966
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200967 RTC_CHECK(last_series);
968 last_series->intervals.emplace_back(last_detector_switch, end_time_);
969
970 TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
971 PointStyle::kHighlight);
972 for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200973 float x = ToCallTimeSec(cluster.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200974 float y = static_cast<float>(cluster.bitrate_bps) / 1000;
975 created_series.points.emplace_back(x, y);
976 }
977
978 TimeSeries result_series("Probing results.", LineStyle::kNone,
979 PointStyle::kHighlight);
Bjorn Terelius7a0bb002018-05-29 14:45:53 +0200980 for (auto& result : parsed_log_.bwe_probe_success_events()) {
981 float x = ToCallTimeSec(result.log_time_us());
982 float y = static_cast<float>(result.bitrate_bps) / 1000;
983 result_series.points.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200984 }
985
986 IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
987 bool previously_in_alr = false;
988 int64_t alr_start = 0;
989 for (auto& alr : parsed_log_.alr_state_events()) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200990 float y = ToCallTimeSec(alr.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200991 if (!previously_in_alr && alr.in_alr) {
992 alr_start = alr.log_time_us();
993 previously_in_alr = true;
994 } else if (previously_in_alr && !alr.in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +0200995 float x = ToCallTimeSec(alr_start);
Ilya Nikolaevskiya4259f62017-12-05 13:19:45 +0100996 alr_state.intervals.emplace_back(x, y);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +0200997 previously_in_alr = false;
Björn Tereliusff612732018-04-25 14:23:01 +0000998 }
Björn Tereliusff612732018-04-25 14:23:01 +0000999 }
1000
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001001 if (previously_in_alr) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001002 float x = ToCallTimeSec(alr_start);
1003 float y = ToCallTimeSec(end_time_);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001004 alr_state.intervals.emplace_back(x, y);
1005 }
1006
1007 if (show_detector_state) {
1008 plot->AppendIntervalSeries(std::move(overusing_series));
1009 plot->AppendIntervalSeries(std::move(underusing_series));
1010 plot->AppendIntervalSeries(std::move(normal_series));
1011 }
1012
1013 if (show_alr_state) {
1014 plot->AppendIntervalSeries(std::move(alr_state));
1015 }
1016 plot->AppendTimeSeries(std::move(loss_series));
1017 plot->AppendTimeSeries(std::move(delay_series));
1018 plot->AppendTimeSeries(std::move(created_series));
1019 plot->AppendTimeSeries(std::move(result_series));
1020
1021 // Overlay the incoming REMB over the outgoing bitrate.
Björn Tereliusff612732018-04-25 14:23:01 +00001022 TimeSeries remb_series("Remb", LineStyle::kStep);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001023 for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001024 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001025 float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
terelius2c8e8a32017-06-02 01:29:48 -07001026 remb_series.points.emplace_back(x, y);
1027 }
1028 plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1029
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001030 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1031 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001032 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001033 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -07001034}
1035
1036// For each SSRC, plot the bandwidth used by that stream.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001037void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1038 Plot* plot) {
1039 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1040 // Filter on SSRC.
1041 if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
terelius6addf492016-08-23 17:34:07 -07001042 continue;
terelius54ce6802016-07-13 06:44:41 -07001043 }
1044
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001045 TimeSeries time_series(GetStreamName(direction, stream.ssrc),
1046 LineStyle::kLine);
1047 auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1048 return packet.total_length * 8.0 / 1000.0;
1049 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001050 auto ToCallTime = [this](int64_t time) {
1051 return this->ToCallTimeSec(time);
1052 };
terelius53dc23c2017-03-13 05:24:05 -07001053 MovingAverage<LoggedRtpPacket, double>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001054 ToCallTime, GetPacketSizeKilobits, stream.packet_view, begin_time_,
1055 end_time_, window_duration_, step_, &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001056 plot->AppendTimeSeries(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -07001057 }
1058
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001059 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1060 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001061 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001062 plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -07001063}
1064
Bjorn Terelius28db2662017-10-04 14:22:43 +02001065void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001066 using RtpPacketType = LoggedRtpPacketOutgoing;
1067 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
Stefan Holmer13181032016-07-29 14:48:54 +02001068
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001069 // TODO(terelius): This could be provided by the parser.
1070 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1071 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1072 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1073 outgoing_rtp.insert(
1074 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Stefan Holmer13181032016-07-29 14:48:54 +02001075 }
1076
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001077 const std::vector<TransportFeedbackType>& incoming_rtcp =
1078 parsed_log_.transport_feedbacks(kIncomingPacket);
Stefan Holmer13181032016-07-29 14:48:54 +02001079
1080 SimulatedClock clock(0);
1081 BitrateObserver observer;
1082 RtcEventLogNullImpl null_event_log;
nisse0245da02016-11-30 03:35:20 -08001083 PacketRouter packet_router;
Stefan Holmer5c8942a2017-08-22 16:16:44 +02001084 PacedSender pacer(&clock, &packet_router, &null_event_log);
1085 SendSideCongestionController cc(&clock, &observer, &null_event_log, &pacer);
Stefan Holmer13181032016-07-29 14:48:54 +02001086 // TODO(holmer): Log the call config and use that here instead.
1087 static const uint32_t kDefaultStartBitrateBps = 300000;
1088 cc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1089
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001090 TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1091 PointStyle::kHighlight);
1092 TimeSeries acked_time_series("Acked bitrate", LineStyle::kLine,
1093 PointStyle::kHighlight);
1094 TimeSeries acked_estimate_time_series(
1095 "Acked bitrate estimate", LineStyle::kLine, PointStyle::kHighlight);
Stefan Holmer13181032016-07-29 14:48:54 +02001096
1097 auto rtp_iterator = outgoing_rtp.begin();
1098 auto rtcp_iterator = incoming_rtcp.begin();
1099
1100 auto NextRtpTime = [&]() {
1101 if (rtp_iterator != outgoing_rtp.end())
1102 return static_cast<int64_t>(rtp_iterator->first);
1103 return std::numeric_limits<int64_t>::max();
1104 };
1105
1106 auto NextRtcpTime = [&]() {
1107 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001108 return static_cast<int64_t>(rtcp_iterator->log_time_us());
Stefan Holmer13181032016-07-29 14:48:54 +02001109 return std::numeric_limits<int64_t>::max();
1110 };
1111
1112 auto NextProcessTime = [&]() {
1113 if (rtcp_iterator != incoming_rtcp.end() ||
1114 rtp_iterator != outgoing_rtp.end()) {
1115 return clock.TimeInMicroseconds() +
1116 std::max<int64_t>(cc.TimeUntilNextProcess() * 1000, 0);
1117 }
1118 return std::numeric_limits<int64_t>::max();
1119 };
1120
Stefan Holmer492ee282016-10-27 17:19:20 +02001121 RateStatistics acked_bitrate(250, 8000);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001122#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1123 // The event_log_visualizer should normally not be compiled with
1124 // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE since the normal plots won't work.
1125 // However, compiling with BWE_TEST_LOGGING, runnning with --plot_sendside_bwe
1126 // and piping the output to plot_dynamics.py can be used as a hack to get the
1127 // internal state of various BWE components. In this case, it is important
1128 // we don't instantiate the AcknowledgedBitrateEstimator both here and in
1129 // SendSideCongestionController since that would lead to duplicate outputs.
1130 AcknowledgedBitrateEstimator acknowledged_bitrate_estimator(
Karl Wiberg918f50c2018-07-05 11:40:33 +02001131 absl::make_unique<BitrateEstimator>());
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001132#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001133 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
Stefan Holmer492ee282016-10-27 17:19:20 +02001134 int64_t last_update_us = 0;
Stefan Holmer13181032016-07-29 14:48:54 +02001135 while (time_us != std::numeric_limits<int64_t>::max()) {
1136 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1137 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001138 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001139 cc.OnTransportFeedback(rtcp_iterator->transport_feedback);
1140 std::vector<PacketFeedback> feedback = cc.GetTransportFeedbackVector();
1141 SortPacketFeedbackVector(&feedback);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001142 absl::optional<uint32_t> bitrate_bps;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001143 if (!feedback.empty()) {
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001144#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001145 acknowledged_bitrate_estimator.IncomingPacketFeedbackVector(feedback);
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001146#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001147 for (const PacketFeedback& packet : feedback)
1148 acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
1149 bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
Stefan Holmer13181032016-07-29 14:48:54 +02001150 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001151 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001152 float y = bitrate_bps.value_or(0) / 1000;
1153 acked_time_series.points.emplace_back(x, y);
1154#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
1155 y = acknowledged_bitrate_estimator.bitrate_bps().value_or(0) / 1000;
1156 acked_estimate_time_series.points.emplace_back(x, y);
1157#endif // !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
Stefan Holmer13181032016-07-29 14:48:54 +02001158 ++rtcp_iterator;
1159 }
1160 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
stefanc3de0332016-08-02 07:22:17 -07001161 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001162 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1163 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1164 RTC_DCHECK(rtp_packet.rtp.header.extension.hasTransportSequenceNumber);
1165 cc.AddPacket(rtp_packet.rtp.header.ssrc,
1166 rtp_packet.rtp.header.extension.transportSequenceNumber,
1167 rtp_packet.rtp.total_length, PacedPacketInfo());
Stefan Holmer13181032016-07-29 14:48:54 +02001168 rtc::SentPacket sent_packet(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001169 rtp_packet.rtp.header.extension.transportSequenceNumber,
1170 rtp_packet.rtp.log_time_us() / 1000);
Stefan Holmer13181032016-07-29 14:48:54 +02001171 cc.OnSentPacket(sent_packet);
1172 }
1173 ++rtp_iterator;
1174 }
stefanc3de0332016-08-02 07:22:17 -07001175 if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1176 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
Stefan Holmer13181032016-07-29 14:48:54 +02001177 cc.Process();
stefanc3de0332016-08-02 07:22:17 -07001178 }
Stefan Holmer492ee282016-10-27 17:19:20 +02001179 if (observer.GetAndResetBitrateUpdated() ||
1180 time_us - last_update_us >= 1e6) {
Stefan Holmer13181032016-07-29 14:48:54 +02001181 uint32_t y = observer.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001182 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Stefan Holmer13181032016-07-29 14:48:54 +02001183 time_series.points.emplace_back(x, y);
Stefan Holmer492ee282016-10-27 17:19:20 +02001184 last_update_us = time_us;
Stefan Holmer13181032016-07-29 14:48:54 +02001185 }
1186 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1187 }
1188 // Add the data set to the plot.
philipel35ba9bd2017-04-19 05:58:51 -07001189 plot->AppendTimeSeries(std::move(time_series));
1190 plot->AppendTimeSeries(std::move(acked_time_series));
Bjorn Terelius6984ad22017-10-24 12:19:45 +02001191 plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
Stefan Holmer13181032016-07-29 14:48:54 +02001192
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001193 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1194 kLeftMargin, kRightMargin);
tereliusdc35dcd2016-08-01 12:03:27 -07001195 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001196 plot->SetTitle("Simulated send-side BWE behavior");
1197}
1198
1199void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001200 using RtpPacketType = LoggedRtpPacketIncoming;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001201 class RembInterceptingPacketRouter : public PacketRouter {
1202 public:
1203 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
1204 uint32_t bitrate_bps) override {
1205 last_bitrate_bps_ = bitrate_bps;
1206 bitrate_updated_ = true;
1207 PacketRouter::OnReceiveBitrateChanged(ssrcs, bitrate_bps);
1208 }
1209 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1210 bool GetAndResetBitrateUpdated() {
1211 bool bitrate_updated = bitrate_updated_;
1212 bitrate_updated_ = false;
1213 return bitrate_updated;
1214 }
1215
1216 private:
1217 uint32_t last_bitrate_bps_;
1218 bool bitrate_updated_;
1219 };
1220
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001221 std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
Bjorn Terelius28db2662017-10-04 14:22:43 +02001222
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001223 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1224 if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) {
1225 for (const auto& rtp_packet : stream.incoming_packets)
1226 incoming_rtp.insert(
1227 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
Bjorn Terelius28db2662017-10-04 14:22:43 +02001228 }
1229 }
1230
1231 SimulatedClock clock(0);
1232 RembInterceptingPacketRouter packet_router;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001233 // TODO(terelius): The PacketRouter is used as the RemoteBitrateObserver.
Bjorn Terelius28db2662017-10-04 14:22:43 +02001234 // Is this intentional?
1235 ReceiveSideCongestionController rscc(&clock, &packet_router);
1236 // TODO(holmer): Log the call config and use that here instead.
1237 // static const uint32_t kDefaultStartBitrateBps = 300000;
1238 // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1239
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001240 TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1241 PointStyle::kHighlight);
1242 TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001243
1244 RateStatistics acked_bitrate(250, 8000);
1245 int64_t last_update_us = 0;
1246 for (const auto& kv : incoming_rtp) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001247 const RtpPacketType& packet = *kv.second;
1248 int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1249 size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1250 clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
Bjorn Terelius28db2662017-10-04 14:22:43 +02001251 clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001252 rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001253 acked_bitrate.Update(payload, arrival_time_ms);
Danil Chapovalov431abd92018-06-18 12:54:17 +02001254 absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001255 if (bitrate_bps) {
1256 uint32_t y = *bitrate_bps / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001257 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001258 acked_time_series.points.emplace_back(x, y);
1259 }
1260 if (packet_router.GetAndResetBitrateUpdated() ||
1261 clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1262 uint32_t y = packet_router.last_bitrate_bps() / 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001263 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Terelius28db2662017-10-04 14:22:43 +02001264 time_series.points.emplace_back(x, y);
1265 last_update_us = clock.TimeInMicroseconds();
1266 }
1267 }
1268 // Add the data set to the plot.
1269 plot->AppendTimeSeries(std::move(time_series));
1270 plot->AppendTimeSeries(std::move(acked_time_series));
1271
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001272 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1273 kLeftMargin, kRightMargin);
Bjorn Terelius28db2662017-10-04 14:22:43 +02001274 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1275 plot->SetTitle("Simulated receive-side BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +02001276}
1277
tereliuse34c19c2016-08-15 08:47:14 -07001278void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001279 using RtpPacketType = LoggedRtpPacketOutgoing;
1280 using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
stefanc3de0332016-08-02 07:22:17 -07001281
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001282 // TODO(terelius): This could be provided by the parser.
1283 std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1284 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1285 for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1286 outgoing_rtp.insert(
1287 std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
stefanc3de0332016-08-02 07:22:17 -07001288 }
1289
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001290 const std::vector<TransportFeedbackType>& incoming_rtcp =
1291 parsed_log_.transport_feedbacks(kIncomingPacket);
stefanc3de0332016-08-02 07:22:17 -07001292
1293 SimulatedClock clock(0);
elad.alon5bbf43f2017-03-09 06:40:08 -08001294 TransportFeedbackAdapter feedback_adapter(&clock);
stefanc3de0332016-08-02 07:22:17 -07001295
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001296 TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone,
1297 PointStyle::kHighlight);
1298 TimeSeries time_series("Network Delay Change", LineStyle::kLine,
1299 PointStyle::kHighlight);
stefanc3de0332016-08-02 07:22:17 -07001300 int64_t estimated_base_delay_ms = std::numeric_limits<int64_t>::max();
1301
1302 auto rtp_iterator = outgoing_rtp.begin();
1303 auto rtcp_iterator = incoming_rtcp.begin();
1304
1305 auto NextRtpTime = [&]() {
1306 if (rtp_iterator != outgoing_rtp.end())
1307 return static_cast<int64_t>(rtp_iterator->first);
1308 return std::numeric_limits<int64_t>::max();
1309 };
1310
1311 auto NextRtcpTime = [&]() {
1312 if (rtcp_iterator != incoming_rtcp.end())
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001313 return static_cast<int64_t>(rtcp_iterator->log_time_us());
stefanc3de0332016-08-02 07:22:17 -07001314 return std::numeric_limits<int64_t>::max();
1315 };
1316
1317 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
stefana0a8ed72017-09-06 02:06:32 -07001318 int64_t prev_y = 0;
stefanc3de0332016-08-02 07:22:17 -07001319 while (time_us != std::numeric_limits<int64_t>::max()) {
1320 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1321 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
1322 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001323 feedback_adapter.OnTransportFeedback(rtcp_iterator->transport_feedback);
1324 std::vector<PacketFeedback> feedback =
1325 feedback_adapter.GetTransportFeedbackVector();
1326 SortPacketFeedbackVector(&feedback);
1327 for (const PacketFeedback& packet : feedback) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001328 float x = ToCallTimeSec(clock.TimeInMicroseconds());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001329 if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
1330 late_feedback_series.points.emplace_back(x, prev_y);
1331 continue;
stefanc3de0332016-08-02 07:22:17 -07001332 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001333 int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1334 prev_y = y;
1335 estimated_base_delay_ms = std::min(y, estimated_base_delay_ms);
1336 time_series.points.emplace_back(x, y);
stefanc3de0332016-08-02 07:22:17 -07001337 }
1338 ++rtcp_iterator;
1339 }
1340 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1341 RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001342 const RtpPacketType& rtp_packet = *rtp_iterator->second;
1343 if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1344 feedback_adapter.AddPacket(
1345 rtp_packet.rtp.header.ssrc,
1346 rtp_packet.rtp.header.extension.transportSequenceNumber,
1347 rtp_packet.rtp.total_length, PacedPacketInfo());
stefanc3de0332016-08-02 07:22:17 -07001348 feedback_adapter.OnSentPacket(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001349 rtp_packet.rtp.header.extension.transportSequenceNumber,
1350 rtp_packet.rtp.log_time_us() / 1000);
stefanc3de0332016-08-02 07:22:17 -07001351 }
1352 ++rtp_iterator;
1353 }
1354 time_us = std::min(NextRtpTime(), NextRtcpTime());
1355 }
1356 // We assume that the base network delay (w/o queues) is the min delay
1357 // observed during the call.
1358 for (TimeSeriesPoint& point : time_series.points)
1359 point.y -= estimated_base_delay_ms;
stefana0a8ed72017-09-06 02:06:32 -07001360 for (TimeSeriesPoint& point : late_feedback_series.points)
1361 point.y -= estimated_base_delay_ms;
stefanc3de0332016-08-02 07:22:17 -07001362 // Add the data set to the plot.
stefana0a8ed72017-09-06 02:06:32 -07001363 plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1364 plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
stefanc3de0332016-08-02 07:22:17 -07001365
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001366 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1367 kLeftMargin, kRightMargin);
stefanc3de0332016-08-02 07:22:17 -07001368 plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
1369 plot->SetTitle("Network Delay Change.");
1370}
stefan08383272016-12-20 08:51:52 -08001371
Bjorn Terelius0295a962017-10-25 17:42:41 +02001372void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001373 for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1374 const std::vector<LoggedRtpPacketOutgoing>& packets =
1375 stream.outgoing_packets;
Bjorn Terelius0295a962017-10-25 17:42:41 +02001376
1377 if (packets.size() < 2) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001378 RTC_LOG(LS_WARNING)
1379 << "Can't estimate a the RTP clock frequency or the "
1380 "pacer delay with less than 2 packets in the stream";
Bjorn Terelius0295a962017-10-25 17:42:41 +02001381 continue;
1382 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001383 int64_t end_time_us = log_segments_.empty()
1384 ? std::numeric_limits<int64_t>::max()
1385 : log_segments_.front().second;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001386 absl::optional<uint32_t> estimated_frequency =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001387 EstimateRtpClockFrequency(packets, end_time_us);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001388 if (!estimated_frequency)
1389 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001390 if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) &&
1391 *estimated_frequency != 90000) {
Mirko Bonadei675513b2017-11-09 11:09:25 +01001392 RTC_LOG(LS_WARNING)
Bjorn Terelius0295a962017-10-25 17:42:41 +02001393 << "Video stream should use a 90 kHz clock but appears to use "
1394 << *estimated_frequency / 1000 << ". Discarding.";
1395 continue;
1396 }
1397
1398 TimeSeries pacer_delay_series(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001399 GetStreamName(kOutgoingPacket, stream.ssrc) + "(" +
Bjorn Terelius0295a962017-10-25 17:42:41 +02001400 std::to_string(*estimated_frequency / 1000) + " kHz)",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001401 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001402 SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1403 uint64_t first_capture_timestamp =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001404 timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1405 uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1406 for (const auto& packet : packets) {
Bjorn Terelius0295a962017-10-25 17:42:41 +02001407 double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001408 packet.rtp.header.timestamp)) -
Bjorn Terelius0295a962017-10-25 17:42:41 +02001409 first_capture_timestamp) /
1410 *estimated_frequency * 1000;
1411 double send_time_ms =
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001412 static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1413 1000;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001414 float x = ToCallTimeSec(packet.rtp.log_time_us());
Bjorn Terelius0295a962017-10-25 17:42:41 +02001415 float y = send_time_ms - capture_time_ms;
1416 pacer_delay_series.points.emplace_back(x, y);
1417 }
1418 plot->AppendTimeSeries(std::move(pacer_delay_series));
1419 }
1420
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001421 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1422 kLeftMargin, kRightMargin);
Bjorn Terelius0295a962017-10-25 17:42:41 +02001423 plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1424 plot->SetTitle(
1425 "Delay from capture to send time. (First packet normalized to 0.)");
1426}
1427
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001428void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1429 Plot* plot) {
1430 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1431 TimeSeries rtp_timestamps(
1432 GetStreamName(direction, stream.ssrc) + " capture-time",
1433 LineStyle::kLine, PointStyle::kHighlight);
1434 for (const auto& packet : stream.packet_view) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001435 float x = ToCallTimeSec(packet.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001436 float y = packet.header.timestamp;
1437 rtp_timestamps.points.emplace_back(x, y);
stefane372d3c2017-02-02 08:04:18 -08001438 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001439 plot->AppendTimeSeries(std::move(rtp_timestamps));
Björn Tereliusff612732018-04-25 14:23:01 +00001440
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001441 TimeSeries rtcp_timestamps(
1442 GetStreamName(direction, stream.ssrc) + " rtcp capture-time",
1443 LineStyle::kLine, PointStyle::kHighlight);
1444 // TODO(terelius): Why only sender reports?
1445 const auto& sender_reports = parsed_log_.sender_reports(direction);
1446 for (const auto& rtcp : sender_reports) {
1447 if (rtcp.sr.sender_ssrc() != stream.ssrc)
1448 continue;
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001449 float x = ToCallTimeSec(rtcp.log_time_us());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001450 float y = rtcp.sr.rtp_timestamp();
1451 rtcp_timestamps.points.emplace_back(x, y);
Björn Tereliusff612732018-04-25 14:23:01 +00001452 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001453 plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
stefane372d3c2017-02-02 08:04:18 -08001454 }
1455
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001456 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1457 kLeftMargin, kRightMargin);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001458 plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1459 plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
stefane372d3c2017-02-02 08:04:18 -08001460}
michaelt6e5b2192017-02-22 07:33:27 -08001461
Bjorn Tereliusb1222c22018-07-24 13:45:31 +02001462void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1463 PacketDirection direction,
1464 rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1465 std::string title,
1466 std::string yaxis_label,
1467 Plot* plot) {
1468 std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1469 const auto& sender_reports = parsed_log_.sender_reports(direction);
1470 for (const auto& rtcp : sender_reports) {
1471 float x = ToCallTimeSec(rtcp.log_time_us());
1472 uint32_t ssrc = rtcp.sr.sender_ssrc();
1473 for (const auto& block : rtcp.sr.report_blocks()) {
1474 float y = fy(block);
1475 auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1476 bool inserted;
1477 if (sr_report_it == sr_reports_by_ssrc.end()) {
1478 std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1479 ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports",
1480 LineStyle::kLine, PointStyle::kHighlight));
1481 }
1482 sr_report_it->second.points.emplace_back(x, y);
1483 }
1484 }
1485 for (auto& kv : sr_reports_by_ssrc) {
1486 plot->AppendTimeSeries(std::move(kv.second));
1487 }
1488
1489 std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1490 const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1491 for (const auto& rtcp : receiver_reports) {
1492 float x = ToCallTimeSec(rtcp.log_time_us());
1493 uint32_t ssrc = rtcp.rr.sender_ssrc();
1494 for (const auto& block : rtcp.rr.report_blocks()) {
1495 float y = fy(block);
1496 auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1497 bool inserted;
1498 if (rr_report_it == rr_reports_by_ssrc.end()) {
1499 std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1500 ssrc,
1501 TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports",
1502 LineStyle::kLine, PointStyle::kHighlight));
1503 }
1504 rr_report_it->second.points.emplace_back(x, y);
1505 }
1506 }
1507 for (auto& kv : rr_reports_by_ssrc) {
1508 plot->AppendTimeSeries(std::move(kv.second));
1509 }
1510
1511 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1512 kLeftMargin, kRightMargin);
1513 plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1514 plot->SetTitle(title);
1515}
1516
michaelt6e5b2192017-02-22 07:33:27 -08001517void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001518 TimeSeries time_series("Audio encoder target bitrate", LineStyle::kLine,
1519 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001520 auto GetAnaBitrateBps = [](const LoggedAudioNetworkAdaptationEvent& ana_event)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001521 -> absl::optional<float> {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001522 if (ana_event.config.bitrate_bps)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001523 return absl::optional<float>(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001524 static_cast<float>(*ana_event.config.bitrate_bps));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001525 return absl::nullopt;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001526 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001527 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1528 return this->ToCallTimeSec(packet.log_time_us());
1529 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001530 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001531 ToCallTime, GetAnaBitrateBps,
1532 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001533 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001534 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1535 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001536 plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
1537 plot->SetTitle("Reported audio encoder target bitrate");
1538}
1539
1540void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001541 TimeSeries time_series("Audio encoder frame length", LineStyle::kLine,
1542 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001543 auto GetAnaFrameLengthMs =
1544 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001545 if (ana_event.config.frame_length_ms)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001546 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001547 static_cast<float>(*ana_event.config.frame_length_ms));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001548 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001549 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001550 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1551 return this->ToCallTimeSec(packet.log_time_us());
1552 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001553 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001554 ToCallTime, GetAnaFrameLengthMs,
1555 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001556 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001557 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1558 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001559 plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
1560 plot->SetTitle("Reported audio encoder frame length");
1561}
1562
terelius2ee076d2017-08-15 02:04:02 -07001563void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) {
philipel35ba9bd2017-04-19 05:58:51 -07001564 TimeSeries time_series("Audio encoder uplink packet loss fraction",
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001565 LineStyle::kLine, PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001566 auto GetAnaPacketLoss =
1567 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001568 if (ana_event.config.uplink_packet_loss_fraction)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001569 return absl::optional<float>(static_cast<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001570 *ana_event.config.uplink_packet_loss_fraction));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001571 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001572 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001573 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1574 return this->ToCallTimeSec(packet.log_time_us());
1575 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001576 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001577 ToCallTime, GetAnaPacketLoss,
1578 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001579 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001580 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1581 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001582 plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
1583 kTopMargin);
1584 plot->SetTitle("Reported audio encoder lost packets");
1585}
1586
1587void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001588 TimeSeries time_series("Audio encoder FEC", LineStyle::kLine,
1589 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001590 auto GetAnaFecEnabled =
1591 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001592 if (ana_event.config.enable_fec)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001593 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001594 static_cast<float>(*ana_event.config.enable_fec));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001595 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001596 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001597 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1598 return this->ToCallTimeSec(packet.log_time_us());
1599 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001600 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001601 ToCallTime, GetAnaFecEnabled,
1602 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001603 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001604 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1605 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001606 plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
1607 plot->SetTitle("Reported audio encoder FEC");
1608}
1609
1610void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001611 TimeSeries time_series("Audio encoder DTX", LineStyle::kLine,
1612 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001613 auto GetAnaDtxEnabled =
1614 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001615 if (ana_event.config.enable_dtx)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001616 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001617 static_cast<float>(*ana_event.config.enable_dtx));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001618 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001619 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001620 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1621 return this->ToCallTimeSec(packet.log_time_us());
1622 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001623 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001624 ToCallTime, GetAnaDtxEnabled,
1625 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001626 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001627 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1628 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001629 plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
1630 plot->SetTitle("Reported audio encoder DTX");
1631}
1632
1633void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) {
Bjorn Tereliusb577d5e2017-11-10 16:21:34 +01001634 TimeSeries time_series("Audio encoder number of channels", LineStyle::kLine,
1635 PointStyle::kHighlight);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001636 auto GetAnaNumChannels =
1637 [](const LoggedAudioNetworkAdaptationEvent& ana_event) {
michaelt6e5b2192017-02-22 07:33:27 -08001638 if (ana_event.config.num_channels)
Danil Chapovalov431abd92018-06-18 12:54:17 +02001639 return absl::optional<float>(
michaelt6e5b2192017-02-22 07:33:27 -08001640 static_cast<float>(*ana_event.config.num_channels));
Danil Chapovalov431abd92018-06-18 12:54:17 +02001641 return absl::optional<float>();
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001642 };
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001643 auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
1644 return this->ToCallTimeSec(packet.log_time_us());
1645 };
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001646 ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001647 ToCallTime, GetAnaNumChannels,
1648 parsed_log_.audio_network_adaptation_events(), &time_series);
philipel35ba9bd2017-04-19 05:58:51 -07001649 plot->AppendTimeSeries(std::move(time_series));
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001650 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1651 kLeftMargin, kRightMargin);
michaelt6e5b2192017-02-22 07:33:27 -08001652 plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
1653 kBottomMargin, kTopMargin);
1654 plot->SetTitle("Reported audio encoder number of channels");
1655}
henrik.lundin3c938fc2017-06-14 06:09:58 -07001656
1657class NetEqStreamInput : public test::NetEqInput {
1658 public:
1659 // Does not take any ownership, and all pointers must refer to valid objects
1660 // that outlive the one constructed.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001661 NetEqStreamInput(const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001662 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001663 absl::optional<int64_t> end_time_ms)
henrik.lundin3c938fc2017-06-14 06:09:58 -07001664 : packet_stream_(*packet_stream),
1665 packet_stream_it_(packet_stream_.begin()),
Minyue Li27e2b7d2018-05-07 15:20:24 +02001666 output_events_it_(output_events->begin()),
1667 output_events_end_(output_events->end()),
1668 end_time_ms_(end_time_ms) {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001669 RTC_DCHECK(packet_stream);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001670 RTC_DCHECK(output_events);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001671 }
1672
Danil Chapovalov431abd92018-06-18 12:54:17 +02001673 absl::optional<int64_t> NextPacketTime() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001674 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001675 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001676 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001677 if (end_time_ms_ && packet_stream_it_->rtp.log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001678 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001679 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001680 return packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001681 }
1682
Danil Chapovalov431abd92018-06-18 12:54:17 +02001683 absl::optional<int64_t> NextOutputEventTime() const override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001684 if (output_events_it_ == output_events_end_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001685 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001686 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001687 if (end_time_ms_ && output_events_it_->log_time_ms() > *end_time_ms_) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001688 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001689 }
Minyue Li27e2b7d2018-05-07 15:20:24 +02001690 return output_events_it_->log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001691 }
1692
1693 std::unique_ptr<PacketData> PopPacket() override {
1694 if (packet_stream_it_ == packet_stream_.end()) {
1695 return std::unique_ptr<PacketData>();
1696 }
1697 std::unique_ptr<PacketData> packet_data(new PacketData());
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001698 packet_data->header = packet_stream_it_->rtp.header;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001699 packet_data->time_ms = packet_stream_it_->rtp.log_time_ms();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001700
1701 // This is a header-only "dummy" packet. Set the payload to all zeros, with
1702 // length according to the virtual length.
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001703 packet_data->payload.SetSize(packet_stream_it_->rtp.total_length -
1704 packet_stream_it_->rtp.header_length);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001705 std::fill_n(packet_data->payload.data(), packet_data->payload.size(), 0);
1706
1707 ++packet_stream_it_;
1708 return packet_data;
1709 }
1710
1711 void AdvanceOutputEvent() override {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001712 if (output_events_it_ != output_events_end_) {
1713 ++output_events_it_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001714 }
1715 }
1716
1717 bool ended() const override { return !NextEventTime(); }
1718
Danil Chapovalov431abd92018-06-18 12:54:17 +02001719 absl::optional<RTPHeader> NextHeader() const override {
henrik.lundin3c938fc2017-06-14 06:09:58 -07001720 if (packet_stream_it_ == packet_stream_.end()) {
Danil Chapovalov431abd92018-06-18 12:54:17 +02001721 return absl::nullopt;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001722 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001723 return packet_stream_it_->rtp.header;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001724 }
1725
1726 private:
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001727 const std::vector<LoggedRtpPacketIncoming>& packet_stream_;
1728 std::vector<LoggedRtpPacketIncoming>::const_iterator packet_stream_it_;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001729 std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_it_;
1730 const std::vector<LoggedAudioPlayoutEvent>::const_iterator output_events_end_;
Danil Chapovalov431abd92018-06-18 12:54:17 +02001731 const absl::optional<int64_t> end_time_ms_;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001732};
1733
1734namespace {
1735// Creates a NetEq test object and all necessary input and output helpers. Runs
1736// the test and returns the NetEqDelayAnalyzer object that was used to
1737// instrument the test.
Minyue Lic6ff7572018-05-04 09:46:44 +02001738std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001739 const std::vector<LoggedRtpPacketIncoming>* packet_stream,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001740 const std::vector<LoggedAudioPlayoutEvent>* output_events,
Danil Chapovalov431abd92018-06-18 12:54:17 +02001741 absl::optional<int64_t> end_time_ms,
henrik.lundin3c938fc2017-06-14 06:09:58 -07001742 const std::string& replacement_file_name,
1743 int file_sample_rate_hz) {
1744 std::unique_ptr<test::NetEqInput> input(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001745 new NetEqStreamInput(packet_stream, output_events, end_time_ms));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001746
1747 constexpr int kReplacementPt = 127;
1748 std::set<uint8_t> cn_types;
1749 std::set<uint8_t> forbidden_types;
1750 input.reset(new test::NetEqReplacementInput(std::move(input), kReplacementPt,
1751 cn_types, forbidden_types));
1752
1753 NetEq::Config config;
1754 config.max_packets_in_buffer = 200;
1755 config.enable_fast_accelerate = true;
1756
1757 std::unique_ptr<test::VoidAudioSink> output(new test::VoidAudioSink());
1758
1759 test::NetEqTest::DecoderMap codecs;
1760
1761 // Create a "replacement decoder" that produces the decoded audio by reading
1762 // from a file rather than from the encoded payloads.
1763 std::unique_ptr<test::ResampleInputAudioFile> replacement_file(
1764 new test::ResampleInputAudioFile(replacement_file_name,
1765 file_sample_rate_hz));
1766 replacement_file->set_output_rate_hz(48000);
1767 std::unique_ptr<AudioDecoder> replacement_decoder(
1768 new test::FakeDecodeFromFile(std::move(replacement_file), 48000, false));
1769 test::NetEqTest::ExtDecoderMap ext_codecs;
1770 ext_codecs[kReplacementPt] = {replacement_decoder.get(),
1771 NetEqDecoder::kDecoderArbitrary,
1772 "replacement codec"};
1773
1774 std::unique_ptr<test::NetEqDelayAnalyzer> delay_cb(
1775 new test::NetEqDelayAnalyzer);
Minyue Lic6ff7572018-05-04 09:46:44 +02001776 std::unique_ptr<test::NetEqStatsGetter> neteq_stats_getter(
1777 new test::NetEqStatsGetter(std::move(delay_cb)));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001778 test::DefaultNetEqTestErrorCallback error_cb;
1779 test::NetEqTest::Callbacks callbacks;
1780 callbacks.error_callback = &error_cb;
Minyue Lic6ff7572018-05-04 09:46:44 +02001781 callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
1782 callbacks.get_audio_callback = neteq_stats_getter.get();
henrik.lundin3c938fc2017-06-14 06:09:58 -07001783
1784 test::NetEqTest test(config, codecs, ext_codecs, std::move(input),
1785 std::move(output), callbacks);
1786 test.Run();
Minyue Lic6ff7572018-05-04 09:46:44 +02001787 return neteq_stats_getter;
henrik.lundin3c938fc2017-06-14 06:09:58 -07001788}
1789} // namespace
1790
Minyue Lic6ff7572018-05-04 09:46:44 +02001791EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq(
henrik.lundin3c938fc2017-06-14 06:09:58 -07001792 const std::string& replacement_file_name,
Minyue Lic6ff7572018-05-04 09:46:44 +02001793 int file_sample_rate_hz) const {
1794 NetEqStatsGetterMap neteq_stats;
1795
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001796 for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001797 const uint32_t ssrc = stream.ssrc;
1798 if (!IsAudioSsrc(kIncomingPacket, ssrc))
1799 continue;
1800 const std::vector<LoggedRtpPacketIncoming>* audio_packets =
1801 &stream.incoming_packets;
1802 if (audio_packets == nullptr) {
1803 // No incoming audio stream found.
1804 continue;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001805 }
henrik.lundin3c938fc2017-06-14 06:09:58 -07001806
Minyue Li27e2b7d2018-05-07 15:20:24 +02001807 RTC_DCHECK(neteq_stats.find(ssrc) == neteq_stats.end());
1808
1809 std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>::const_iterator
1810 output_events_it = parsed_log_.audio_playout_events().find(ssrc);
1811 if (output_events_it == parsed_log_.audio_playout_events().end()) {
1812 // Could not find output events with SSRC matching the input audio stream.
1813 // Using the first available stream of output events.
1814 output_events_it = parsed_log_.audio_playout_events().cbegin();
1815 }
1816
Danil Chapovalov431abd92018-06-18 12:54:17 +02001817 absl::optional<int64_t> end_time_ms =
Minyue Li27e2b7d2018-05-07 15:20:24 +02001818 log_segments_.empty()
Danil Chapovalov431abd92018-06-18 12:54:17 +02001819 ? absl::nullopt
1820 : absl::optional<int64_t>(log_segments_.front().second / 1000);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001821
1822 neteq_stats[ssrc] = CreateNetEqTestAndRun(
1823 audio_packets, &output_events_it->second, end_time_ms,
1824 replacement_file_name, file_sample_rate_hz);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001825 }
1826
Minyue Lic6ff7572018-05-04 09:46:44 +02001827 return neteq_stats;
1828}
1829
Minyue Lic97933f2018-08-10 12:51:15 +02001830// Given a NetEqStatsGetter and the SSRC that the NetEqStatsGetter was created
1831// for, this method generates a plot for the jitter buffer delay profile.
Minyue Lic6ff7572018-05-04 09:46:44 +02001832void EventLogAnalyzer::CreateAudioJitterBufferGraph(
Minyue Li01d2a672018-06-21 21:17:19 +02001833 uint32_t ssrc,
1834 const test::NetEqStatsGetter* stats_getter,
Minyue Lic6ff7572018-05-04 09:46:44 +02001835 Plot* plot) const {
Minyue Li45fc6df2018-06-21 11:47:14 +02001836 test::NetEqDelayAnalyzer::Delays arrival_delay_ms;
1837 test::NetEqDelayAnalyzer::Delays corrected_arrival_delay_ms;
1838 test::NetEqDelayAnalyzer::Delays playout_delay_ms;
1839 test::NetEqDelayAnalyzer::Delays target_delay_ms;
1840
Minyue Li01d2a672018-06-21 21:17:19 +02001841 stats_getter->delay_analyzer()->CreateGraphs(
Minyue Li45fc6df2018-06-21 11:47:14 +02001842 &arrival_delay_ms, &corrected_arrival_delay_ms, &playout_delay_ms,
1843 &target_delay_ms);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001844
Minyue Lic97933f2018-08-10 12:51:15 +02001845 TimeSeries time_series_packet_arrival("packet arrival delay",
1846 LineStyle::kLine);
1847 TimeSeries time_series_relative_packet_arrival(
1848 "Relative packet arrival delay", LineStyle::kLine);
1849 TimeSeries time_series_play_time("Playout delay", LineStyle::kLine);
1850 TimeSeries time_series_target_time("Target delay", LineStyle::kLine,
1851 PointStyle::kHighlight);
Minyue Li45fc6df2018-06-21 11:47:14 +02001852
1853 for (const auto& data : arrival_delay_ms) {
1854 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1855 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001856 time_series_packet_arrival.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001857 }
1858 for (const auto& data : corrected_arrival_delay_ms) {
1859 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1860 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001861 time_series_relative_packet_arrival.points.emplace_back(
Minyue Li45fc6df2018-06-21 11:47:14 +02001862 TimeSeriesPoint(x, y));
1863 }
1864 for (const auto& data : playout_delay_ms) {
1865 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1866 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001867 time_series_play_time.points.emplace_back(TimeSeriesPoint(x, y));
Minyue Li45fc6df2018-06-21 11:47:14 +02001868 }
1869 for (const auto& data : target_delay_ms) {
1870 const float x = ToCallTimeSec(data.first * 1000); // ms to us.
1871 const float y = data.second;
Minyue Lic97933f2018-08-10 12:51:15 +02001872 time_series_target_time.points.emplace_back(TimeSeriesPoint(x, y));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001873 }
1874
Minyue Lic97933f2018-08-10 12:51:15 +02001875 plot->AppendTimeSeries(std::move(time_series_packet_arrival));
1876 plot->AppendTimeSeries(std::move(time_series_relative_packet_arrival));
1877 plot->AppendTimeSeries(std::move(time_series_play_time));
1878 plot->AppendTimeSeries(std::move(time_series_target_time));
henrik.lundin3c938fc2017-06-14 06:09:58 -07001879
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001880 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1881 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001882 plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin,
1883 kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001884 plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
1885}
1886
Minyue Lic9ac93f2018-06-26 13:01:32 +02001887template <typename NetEqStatsType>
1888void EventLogAnalyzer::CreateNetEqStatsGraphInternal(
Minyue Li27e2b7d2018-05-07 15:20:24 +02001889 const NetEqStatsGetterMap& neteq_stats,
Minyue Lic9ac93f2018-06-26 13:01:32 +02001890 rtc::FunctionView<const std::vector<std::pair<int64_t, NetEqStatsType>>*(
1891 const test::NetEqStatsGetter*)> data_extractor,
1892 rtc::FunctionView<float(const NetEqStatsType&)> stats_extractor,
Minyue Li27e2b7d2018-05-07 15:20:24 +02001893 const std::string& plot_name,
1894 Plot* plot) const {
Minyue Li27e2b7d2018-05-07 15:20:24 +02001895 std::map<uint32_t, TimeSeries> time_series;
Minyue Li27e2b7d2018-05-07 15:20:24 +02001896
1897 for (const auto& st : neteq_stats) {
1898 const uint32_t ssrc = st.first;
Minyue Lic9ac93f2018-06-26 13:01:32 +02001899 const std::vector<std::pair<int64_t, NetEqStatsType>>* data_vector =
1900 data_extractor(st.second.get());
1901 for (const auto& data : *data_vector) {
1902 const float time = ToCallTimeSec(data.first * 1000); // ms to us.
1903 const float value = stats_extractor(data.second);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001904 time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
Minyue Li27e2b7d2018-05-07 15:20:24 +02001905 }
1906 }
1907
1908 for (auto& series : time_series) {
1909 series.second.label = GetStreamName(kIncomingPacket, series.first);
1910 series.second.line_style = LineStyle::kLine;
1911 plot->AppendTimeSeries(std::move(series.second));
1912 }
1913
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001914 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1915 kLeftMargin, kRightMargin);
Minyue Li45fc6df2018-06-21 11:47:14 +02001916 plot->SetSuggestedYAxis(0, 1, plot_name, kBottomMargin, kTopMargin);
Minyue Li27e2b7d2018-05-07 15:20:24 +02001917 plot->SetTitle(plot_name);
henrik.lundin3c938fc2017-06-14 06:09:58 -07001918}
Bjorn Terelius2eb31882017-11-30 15:15:25 +01001919
Minyue Lic9ac93f2018-06-26 13:01:32 +02001920void EventLogAnalyzer::CreateNetEqNetworkStatsGraph(
1921 const NetEqStatsGetterMap& neteq_stats,
1922 rtc::FunctionView<float(const NetEqNetworkStatistics&)> stats_extractor,
1923 const std::string& plot_name,
1924 Plot* plot) const {
1925 CreateNetEqStatsGraphInternal<NetEqNetworkStatistics>(
1926 neteq_stats,
1927 [](const test::NetEqStatsGetter* stats_getter) {
1928 return stats_getter->stats();
1929 },
1930 stats_extractor, plot_name, plot);
1931}
1932
1933void EventLogAnalyzer::CreateNetEqLifetimeStatsGraph(
1934 const NetEqStatsGetterMap& neteq_stats,
1935 rtc::FunctionView<float(const NetEqLifetimeStatistics&)> stats_extractor,
1936 const std::string& plot_name,
1937 Plot* plot) const {
1938 CreateNetEqStatsGraphInternal<NetEqLifetimeStatistics>(
1939 neteq_stats,
1940 [](const test::NetEqStatsGetter* stats_getter) {
1941 return stats_getter->lifetime_stats();
1942 },
1943 stats_extractor, plot_name, plot);
1944}
1945
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001946void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1947 std::map<uint32_t, TimeSeries> configs_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001948 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001949 if (configs_by_cp_id.find(config.candidate_pair_id) ==
1950 configs_by_cp_id.end()) {
1951 const std::string candidate_pair_desc =
1952 GetCandidatePairLogDescriptionAsString(config);
Qingsi Wang93a84392018-01-30 17:13:09 -08001953 configs_by_cp_id[config.candidate_pair_id] =
1954 TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1955 candidate_pair_desc,
1956 LineStyle::kNone, PointStyle::kHighlight);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001957 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1958 candidate_pair_desc;
1959 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001960 float x = ToCallTimeSec(config.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001961 float y = static_cast<float>(config.type);
1962 configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1963 }
1964
1965 // TODO(qingsi): There can be a large number of candidate pairs generated by
1966 // certain calls and the frontend cannot render the chart in this case due to
1967 // the failure of generating a palette with the same number of colors.
1968 for (auto& kv : configs_by_cp_id) {
1969 plot->AppendTimeSeries(std::move(kv.second));
1970 }
1971
Stefan Holmer1d4a2272018-05-24 13:48:09 +02001972 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
1973 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001974 plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
1975 kTopMargin);
1976 plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1977}
1978
1979std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1980 uint32_t candidate_pair_id) {
1981 if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1982 candidate_pair_desc_by_id_.end()) {
1983 return candidate_pair_desc_by_id_[candidate_pair_id];
1984 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02001985 for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08001986 // TODO(qingsi): Add the handling of the "Updated" config event after the
1987 // visualization of property change for candidate pairs is introduced.
1988 if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1989 candidate_pair_desc_by_id_.end()) {
1990 const std::string candidate_pair_desc =
1991 GetCandidatePairLogDescriptionAsString(config);
1992 candidate_pair_desc_by_id_[config.candidate_pair_id] =
1993 candidate_pair_desc;
1994 }
1995 }
1996 return candidate_pair_desc_by_id_[candidate_pair_id];
1997}
1998
1999void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
2000 std::map<uint32_t, TimeSeries> checks_by_cp_id;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002001 for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002002 if (checks_by_cp_id.find(event.candidate_pair_id) ==
2003 checks_by_cp_id.end()) {
2004 checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
Qingsi Wang93a84392018-01-30 17:13:09 -08002005 "[" + std::to_string(event.candidate_pair_id) + "]" +
2006 GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002007 LineStyle::kNone, PointStyle::kHighlight);
2008 }
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002009 float x = ToCallTimeSec(event.log_time_us());
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002010 float y = static_cast<float>(event.type);
2011 checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
2012 }
2013
2014 // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
2015 for (auto& kv : checks_by_cp_id) {
2016 plot->AppendTimeSeries(std::move(kv.second));
2017 }
2018
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002019 plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
2020 kLeftMargin, kRightMargin);
Qingsi Wang8eca1ff2018-02-02 11:49:44 -08002021 plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
2022 kTopMargin);
2023 plot->SetTitle("[IceEventLog] ICE connectivity checks");
2024}
2025
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002026void EventLogAnalyzer::PrintNotifications(FILE* file) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002027 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002028 for (const auto& alert : incoming_rtp_recv_time_gaps_) {
2029 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2030 }
2031 for (const auto& alert : incoming_rtcp_recv_time_gaps_) {
2032 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2033 }
2034 for (const auto& alert : outgoing_rtp_send_time_gaps_) {
2035 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2036 }
2037 for (const auto& alert : outgoing_rtcp_send_time_gaps_) {
2038 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2039 }
2040 for (const auto& alert : incoming_seq_num_jumps_) {
2041 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2042 }
2043 for (const auto& alert : incoming_capture_time_jumps_) {
2044 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2045 }
2046 for (const auto& alert : outgoing_seq_num_jumps_) {
2047 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2048 }
2049 for (const auto& alert : outgoing_capture_time_jumps_) {
2050 fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str());
2051 }
2052 for (const auto& alert : outgoing_high_loss_alerts_) {
2053 fprintf(file, " : %s\n", alert.ToString().c_str());
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002054 }
2055 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
2056}
2057
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002058void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) {
2059 // With 100 packets/s (~800kbps), false positives would require 10 s without
2060 // data.
2061 constexpr int64_t kMaxSeqNumJump = 1000;
2062 // With a 90 kHz clock, false positives would require 10 s without data.
2063 constexpr int64_t kMaxCaptureTimeJump = 900000;
2064
2065 int64_t end_time_us = log_segments_.empty()
2066 ? std::numeric_limits<int64_t>::max()
2067 : log_segments_.front().second;
2068
2069 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002070 absl::optional<int64_t> last_seq_num;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002071 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Danil Chapovalov431abd92018-06-18 12:54:17 +02002072 absl::optional<int64_t> last_capture_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002073 // Check for gaps in sequence numbers and capture timestamps.
2074 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2075 for (const auto& packet : stream.packet_view) {
2076 if (packet.log_time_us() > end_time_us) {
2077 // Only process the first (LOG_START, LOG_END) segment.
2078 break;
2079 }
2080
2081 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
2082 if (last_seq_num.has_value() &&
2083 std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002084 Alert_SeqNumJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002085 packet.header.ssrc);
2086 }
2087 last_seq_num.emplace(seq_num);
2088
2089 int64_t capture_time =
2090 capture_time_unwrapper.Unwrap(packet.header.timestamp);
2091 if (last_capture_time.has_value() &&
2092 std::abs(capture_time - last_capture_time.value()) >
2093 kMaxCaptureTimeJump) {
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002094 Alert_CaptureTimeJump(direction, ToCallTimeSec(packet.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002095 packet.header.ssrc);
2096 }
2097 last_capture_time.emplace(capture_time);
2098 }
2099 }
2100}
2101
2102void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) {
2103 constexpr int64_t kMaxRtpTransmissionGap = 500000;
2104 constexpr int64_t kMaxRtcpTransmissionGap = 2000000;
2105 int64_t end_time_us = log_segments_.empty()
2106 ? std::numeric_limits<int64_t>::max()
2107 : log_segments_.front().second;
2108
2109 // TODO(terelius): The parser could provide a list of all packets, ordered
2110 // by time, for each direction.
2111 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
2112 for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
2113 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
2114 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
2115 }
Danil Chapovalov431abd92018-06-18 12:54:17 +02002116 absl::optional<int64_t> last_rtp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002117 for (const auto& kv : rtp_in_direction) {
2118 int64_t timestamp = kv.first;
2119 if (timestamp > end_time_us) {
2120 // Only process the first (LOG_START, LOG_END) segment.
2121 break;
2122 }
2123 int64_t duration = timestamp - last_rtp_time.value_or(0);
2124 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
2125 // No packet sent/received for more than 500 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002126 Alert_RtpLogTimeGap(direction, ToCallTimeSec(timestamp), duration / 1000);
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002127 }
2128 last_rtp_time.emplace(timestamp);
2129 }
2130
Danil Chapovalov431abd92018-06-18 12:54:17 +02002131 absl::optional<int64_t> last_rtcp_time;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002132 if (direction == kIncomingPacket) {
2133 for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) {
2134 if (rtcp.log_time_us() > end_time_us) {
2135 // Only process the first (LOG_START, LOG_END) segment.
2136 break;
2137 }
2138 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2139 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2140 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002141 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002142 duration / 1000);
2143 }
2144 last_rtcp_time.emplace(rtcp.log_time_us());
2145 }
2146 } else {
2147 for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) {
2148 if (rtcp.log_time_us() > end_time_us) {
2149 // Only process the first (LOG_START, LOG_END) segment.
2150 break;
2151 }
2152 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
2153 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
2154 // No feedback sent/received for more than 2000 ms.
Stefan Holmer1d4a2272018-05-24 13:48:09 +02002155 Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002156 duration / 1000);
2157 }
2158 last_rtcp_time.emplace(rtcp.log_time_us());
2159 }
2160 }
2161}
2162
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002163// TODO(terelius): Notifications could possibly be generated by the same code
2164// that produces the graphs. There is some code duplication that could be
2165// avoided, but that might be solved anyway when we move functionality from the
2166// analyzer to the parser.
2167void EventLogAnalyzer::CreateTriageNotifications() {
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002168 CreateStreamGapAlerts(kIncomingPacket);
2169 CreateStreamGapAlerts(kOutgoingPacket);
2170 CreateTransmissionGapAlerts(kIncomingPacket);
2171 CreateTransmissionGapAlerts(kOutgoingPacket);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002172
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002173 int64_t end_time_us = log_segments_.empty()
2174 ? std::numeric_limits<int64_t>::max()
2175 : log_segments_.front().second;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002176
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002177 constexpr double kMaxLossFraction = 0.05;
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002178 // Loss feedback
2179 int64_t total_lost_packets = 0;
2180 int64_t total_expected_packets = 0;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002181 for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
2182 if (bwe_update.log_time_us() > end_time_us) {
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002183 // Only process the first (LOG_START, LOG_END) segment.
2184 break;
2185 }
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002186 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002187 bwe_update.expected_packets;
2188 total_lost_packets += lost_packets;
2189 total_expected_packets += bwe_update.expected_packets;
2190 }
2191 double avg_outgoing_loss =
2192 static_cast<double>(total_lost_packets) / total_expected_packets;
Bjorn Tereliusc4ca1d32018-04-27 14:33:34 +02002193 if (avg_outgoing_loss > kMaxLossFraction) {
2194 Alert_OutgoingHighLoss(avg_outgoing_loss);
Bjorn Terelius2eb31882017-11-30 15:15:25 +01002195 }
2196}
2197
terelius54ce6802016-07-13 06:44:41 -07002198} // namespace webrtc