blob: 26be553f9a17f9a633c2ab61c6a24294f87918be [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
11#include "webrtc/tools/event_log_visualizer/analyzer.h"
12
13#include <algorithm>
14#include <limits>
15#include <map>
16#include <sstream>
17#include <string>
18#include <utility>
19
20#include "webrtc/audio_receive_stream.h"
21#include "webrtc/audio_send_stream.h"
22#include "webrtc/base/checks.h"
stefan6a850c32016-07-29 10:28:08 -070023#include "webrtc/base/logging.h"
terelius54ce6802016-07-13 06:44:41 -070024#include "webrtc/call.h"
25#include "webrtc/common_types.h"
Stefan Holmer13181032016-07-29 14:48:54 +020026#include "webrtc/modules/congestion_controller/include/congestion_controller.h"
terelius54ce6802016-07-13 06:44:41 -070027#include "webrtc/modules/rtp_rtcp/include/rtp_rtcp.h"
28#include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
29#include "webrtc/modules/rtp_rtcp/source/rtp_utility.h"
Stefan Holmer13181032016-07-29 14:48:54 +020030#include "webrtc/modules/rtp_rtcp/source/rtcp_utility.h"
31#include "webrtc/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
terelius54ce6802016-07-13 06:44:41 -070032#include "webrtc/video_receive_stream.h"
33#include "webrtc/video_send_stream.h"
34
35namespace {
36
37std::string SsrcToString(uint32_t ssrc) {
38 std::stringstream ss;
39 ss << "SSRC " << ssrc;
40 return ss.str();
41}
42
43// Checks whether an SSRC is contained in the list of desired SSRCs.
44// Note that an empty SSRC list matches every SSRC.
45bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
46 if (desired_ssrc.size() == 0)
47 return true;
48 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
49 desired_ssrc.end();
50}
51
52double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
53 // The timestamp is a fixed point representation with 6 bits for seconds
54 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
55 // time in seconds and then multiply by 1000000 to convert to microseconds.
56 static constexpr double kTimestampToMicroSec =
57 1000000.0 / static_cast<double>(1 << 18);
58 return abs_send_time * kTimestampToMicroSec;
59}
60
61// Computes the difference |later| - |earlier| where |later| and |earlier|
62// are counters that wrap at |modulus|. The difference is chosen to have the
63// least absolute value. For example if |modulus| is 8, then the difference will
64// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
65// be in [-4, 4].
66int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
67 RTC_DCHECK_LE(1, modulus);
68 RTC_DCHECK_LT(later, modulus);
69 RTC_DCHECK_LT(earlier, modulus);
70 int64_t difference =
71 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
72 int64_t max_difference = modulus / 2;
73 int64_t min_difference = max_difference - modulus + 1;
74 if (difference > max_difference) {
75 difference -= modulus;
76 }
77 if (difference < min_difference) {
78 difference += modulus;
79 }
80 return difference;
81}
82
stefan6a850c32016-07-29 10:28:08 -070083void RegisterHeaderExtensions(
84 const std::vector<webrtc::RtpExtension>& extensions,
85 webrtc::RtpHeaderExtensionMap* extension_map) {
86 extension_map->Erase();
87 for (const webrtc::RtpExtension& extension : extensions) {
88 extension_map->Register(webrtc::StringToRtpExtensionType(extension.uri),
89 extension.id);
90 }
91}
92
terelius54ce6802016-07-13 06:44:41 -070093const double kXMargin = 1.02;
94const double kYMargin = 1.1;
95const double kDefaultXMin = -1;
96const double kDefaultYMin = -1;
97
98} // namespace
99
100namespace webrtc {
101namespace plotting {
102
terelius88e64e52016-07-19 01:51:06 -0700103
104bool EventLogAnalyzer::StreamId::operator<(const StreamId& other) const {
105 if (ssrc_ < other.ssrc_) {
106 return true;
107 }
108 if (ssrc_ == other.ssrc_) {
Stefan Holmer13181032016-07-29 14:48:54 +0200109 if (direction_ < other.direction_) {
terelius88e64e52016-07-19 01:51:06 -0700110 return true;
111 }
terelius88e64e52016-07-19 01:51:06 -0700112 }
113 return false;
114}
115
116bool EventLogAnalyzer::StreamId::operator==(const StreamId& other) const {
Stefan Holmer13181032016-07-29 14:48:54 +0200117 return ssrc_ == other.ssrc_ && direction_ == other.direction_;
terelius88e64e52016-07-19 01:51:06 -0700118}
119
120
terelius54ce6802016-07-13 06:44:41 -0700121EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log)
122 : parsed_log_(log), window_duration_(250000), step_(10000) {
123 uint64_t first_timestamp = std::numeric_limits<uint64_t>::max();
124 uint64_t last_timestamp = std::numeric_limits<uint64_t>::min();
terelius88e64e52016-07-19 01:51:06 -0700125
Stefan Holmer13181032016-07-29 14:48:54 +0200126 // Maps a stream identifier consisting of ssrc and direction
terelius88e64e52016-07-19 01:51:06 -0700127 // to the header extensions used by that stream,
128 std::map<StreamId, RtpHeaderExtensionMap> extension_maps;
129
130 PacketDirection direction;
terelius88e64e52016-07-19 01:51:06 -0700131 uint8_t header[IP_PACKET_SIZE];
132 size_t header_length;
133 size_t total_length;
134
terelius54ce6802016-07-13 06:44:41 -0700135 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
136 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
terelius88e64e52016-07-19 01:51:06 -0700137 if (event_type != ParsedRtcEventLog::VIDEO_RECEIVER_CONFIG_EVENT &&
138 event_type != ParsedRtcEventLog::VIDEO_SENDER_CONFIG_EVENT &&
139 event_type != ParsedRtcEventLog::AUDIO_RECEIVER_CONFIG_EVENT &&
140 event_type != ParsedRtcEventLog::AUDIO_SENDER_CONFIG_EVENT) {
141 uint64_t timestamp = parsed_log_.GetTimestamp(i);
142 first_timestamp = std::min(first_timestamp, timestamp);
143 last_timestamp = std::max(last_timestamp, timestamp);
144 }
145
146 switch (parsed_log_.GetEventType(i)) {
147 case ParsedRtcEventLog::VIDEO_RECEIVER_CONFIG_EVENT: {
148 VideoReceiveStream::Config config(nullptr);
149 parsed_log_.GetVideoReceiveConfig(i, &config);
Stefan Holmer13181032016-07-29 14:48:54 +0200150 StreamId stream(config.rtp.remote_ssrc, kIncomingPacket);
stefan6a850c32016-07-29 10:28:08 -0700151 RegisterHeaderExtensions(config.rtp.extensions,
152 &extension_maps[stream]);
153 for (auto kv : config.rtp.rtx) {
154 StreamId rtx_stream(kv.second.ssrc, kIncomingPacket);
155 RegisterHeaderExtensions(config.rtp.extensions,
156 &extension_maps[rtx_stream]);
terelius88e64e52016-07-19 01:51:06 -0700157 }
158 break;
159 }
160 case ParsedRtcEventLog::VIDEO_SENDER_CONFIG_EVENT: {
161 VideoSendStream::Config config(nullptr);
162 parsed_log_.GetVideoSendConfig(i, &config);
163 for (auto ssrc : config.rtp.ssrcs) {
Stefan Holmer13181032016-07-29 14:48:54 +0200164 StreamId stream(ssrc, kOutgoingPacket);
stefan6a850c32016-07-29 10:28:08 -0700165 RegisterHeaderExtensions(config.rtp.extensions,
166 &extension_maps[stream]);
167 }
168 for (auto ssrc : config.rtp.rtx.ssrcs) {
169 StreamId stream(ssrc, kOutgoingPacket);
170 RegisterHeaderExtensions(config.rtp.extensions,
171 &extension_maps[stream]);
terelius88e64e52016-07-19 01:51:06 -0700172 }
173 break;
174 }
175 case ParsedRtcEventLog::AUDIO_RECEIVER_CONFIG_EVENT: {
176 AudioReceiveStream::Config config;
177 // TODO(terelius): Parse the audio configs once we have them.
178 break;
179 }
180 case ParsedRtcEventLog::AUDIO_SENDER_CONFIG_EVENT: {
181 AudioSendStream::Config config(nullptr);
182 // TODO(terelius): Parse the audio configs once we have them.
183 break;
184 }
185 case ParsedRtcEventLog::RTP_EVENT: {
Stefan Holmer13181032016-07-29 14:48:54 +0200186 MediaType media_type;
terelius88e64e52016-07-19 01:51:06 -0700187 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
188 &header_length, &total_length);
189 // Parse header to get SSRC.
190 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
191 RTPHeader parsed_header;
192 rtp_parser.Parse(&parsed_header);
Stefan Holmer13181032016-07-29 14:48:54 +0200193 StreamId stream(parsed_header.ssrc, direction);
terelius88e64e52016-07-19 01:51:06 -0700194 // Look up the extension_map and parse it again to get the extensions.
195 if (extension_maps.count(stream) == 1) {
196 RtpHeaderExtensionMap* extension_map = &extension_maps[stream];
197 rtp_parser.Parse(&parsed_header, extension_map);
198 }
199 uint64_t timestamp = parsed_log_.GetTimestamp(i);
200 rtp_packets_[stream].push_back(
Stefan Holmer13181032016-07-29 14:48:54 +0200201 LoggedRtpPacket(timestamp, parsed_header, total_length));
terelius88e64e52016-07-19 01:51:06 -0700202 break;
203 }
204 case ParsedRtcEventLog::RTCP_EVENT: {
Stefan Holmer13181032016-07-29 14:48:54 +0200205 uint8_t packet[IP_PACKET_SIZE];
206 MediaType media_type;
207 parsed_log_.GetRtcpPacket(i, &direction, &media_type, packet,
208 &total_length);
209
210 RtpUtility::RtpHeaderParser rtp_parser(packet, total_length);
211 RTPHeader parsed_header;
212 RTC_CHECK(rtp_parser.ParseRtcp(&parsed_header));
213 uint32_t ssrc = parsed_header.ssrc;
214
215 RTCPUtility::RTCPParserV2 rtcp_parser(packet, total_length, true);
216 RTC_CHECK(rtcp_parser.IsValid());
217
218 RTCPUtility::RTCPPacketTypes packet_type = rtcp_parser.Begin();
219 while (packet_type != RTCPUtility::RTCPPacketTypes::kInvalid) {
220 switch (packet_type) {
221 case RTCPUtility::RTCPPacketTypes::kTransportFeedback: {
222 // Currently feedback is logged twice, both for audio and video.
223 // Only act on one of them.
224 if (media_type == MediaType::VIDEO) {
225 std::unique_ptr<rtcp::RtcpPacket> rtcp_packet(
226 rtcp_parser.ReleaseRtcpPacket());
227 StreamId stream(ssrc, direction);
228 uint64_t timestamp = parsed_log_.GetTimestamp(i);
229 rtcp_packets_[stream].push_back(LoggedRtcpPacket(
230 timestamp, kRtcpTransportFeedback, std::move(rtcp_packet)));
231 }
232 break;
233 }
234 default:
235 break;
236 }
237 rtcp_parser.Iterate();
238 packet_type = rtcp_parser.PacketType();
239 }
terelius88e64e52016-07-19 01:51:06 -0700240 break;
241 }
242 case ParsedRtcEventLog::LOG_START: {
243 break;
244 }
245 case ParsedRtcEventLog::LOG_END: {
246 break;
247 }
248 case ParsedRtcEventLog::BWE_PACKET_LOSS_EVENT: {
terelius8058e582016-07-25 01:32:41 -0700249 BwePacketLossEvent bwe_update;
250 bwe_update.timestamp = parsed_log_.GetTimestamp(i);
251 parsed_log_.GetBwePacketLossEvent(i, &bwe_update.new_bitrate,
252 &bwe_update.fraction_loss,
253 &bwe_update.expected_packets);
254 bwe_loss_updates_.push_back(bwe_update);
terelius88e64e52016-07-19 01:51:06 -0700255 break;
256 }
257 case ParsedRtcEventLog::BWE_PACKET_DELAY_EVENT: {
258 break;
259 }
260 case ParsedRtcEventLog::AUDIO_PLAYOUT_EVENT: {
261 break;
262 }
263 case ParsedRtcEventLog::UNKNOWN_EVENT: {
264 break;
265 }
266 }
terelius54ce6802016-07-13 06:44:41 -0700267 }
terelius88e64e52016-07-19 01:51:06 -0700268
terelius54ce6802016-07-13 06:44:41 -0700269 if (last_timestamp < first_timestamp) {
270 // No useful events in the log.
271 first_timestamp = last_timestamp = 0;
272 }
273 begin_time_ = first_timestamp;
274 end_time_ = last_timestamp;
275}
276
Stefan Holmer13181032016-07-29 14:48:54 +0200277class BitrateObserver : public CongestionController::Observer,
278 public RemoteBitrateObserver {
279 public:
280 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
281
282 void OnNetworkChanged(uint32_t bitrate_bps,
283 uint8_t fraction_loss,
284 int64_t rtt_ms) override {
285 last_bitrate_bps_ = bitrate_bps;
286 bitrate_updated_ = true;
287 }
288
289 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
290 uint32_t bitrate) override {}
291
292 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
293 bool GetAndResetBitrateUpdated() {
294 bool bitrate_updated = bitrate_updated_;
295 bitrate_updated_ = false;
296 return bitrate_updated;
297 }
298
299 private:
300 uint32_t last_bitrate_bps_;
301 bool bitrate_updated_;
302};
303
terelius54ce6802016-07-13 06:44:41 -0700304void EventLogAnalyzer::CreatePacketGraph(PacketDirection desired_direction,
305 Plot* plot) {
306 std::map<uint32_t, TimeSeries> time_series;
307
308 PacketDirection direction;
309 MediaType media_type;
310 uint8_t header[IP_PACKET_SIZE];
311 size_t header_length, total_length;
312 float max_y = 0;
313
314 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
315 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
316 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
317 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
318 &header_length, &total_length);
319 if (direction == desired_direction) {
320 // Parse header to get SSRC.
321 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
322 RTPHeader parsed_header;
323 rtp_parser.Parse(&parsed_header);
324 // Filter on SSRC.
325 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
326 uint64_t timestamp = parsed_log_.GetTimestamp(i);
327 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
328 float y = total_length;
329 max_y = std::max(max_y, y);
330 time_series[parsed_header.ssrc].points.push_back(
331 TimeSeriesPoint(x, y));
332 }
333 }
334 }
335 }
336
337 // Set labels and put in graph.
338 for (auto& kv : time_series) {
339 kv.second.label = SsrcToString(kv.first);
340 kv.second.style = BAR_GRAPH;
341 plot->series.push_back(std::move(kv.second));
342 }
343
344 plot->xaxis_min = kDefaultXMin;
345 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
346 plot->xaxis_label = "Time (s)";
347 plot->yaxis_min = kDefaultYMin;
348 plot->yaxis_max = max_y * kYMargin;
349 plot->yaxis_label = "Packet size (bytes)";
350 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
351 plot->title = "Incoming RTP packets";
352 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
353 plot->title = "Outgoing RTP packets";
354 }
355}
356
357// For each SSRC, plot the time between the consecutive playouts.
358void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
359 std::map<uint32_t, TimeSeries> time_series;
360 std::map<uint32_t, uint64_t> last_playout;
361
362 uint32_t ssrc;
363 float max_y = 0;
364
365 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
366 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
367 if (event_type == ParsedRtcEventLog::AUDIO_PLAYOUT_EVENT) {
368 parsed_log_.GetAudioPlayout(i, &ssrc);
369 uint64_t timestamp = parsed_log_.GetTimestamp(i);
370 if (MatchingSsrc(ssrc, desired_ssrc_)) {
371 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
372 float y = static_cast<float>(timestamp - last_playout[ssrc]) / 1000;
373 if (time_series[ssrc].points.size() == 0) {
374 // There were no previusly logged playout for this SSRC.
375 // Generate a point, but place it on the x-axis.
376 y = 0;
377 }
378 max_y = std::max(max_y, y);
379 time_series[ssrc].points.push_back(TimeSeriesPoint(x, y));
380 last_playout[ssrc] = timestamp;
381 }
382 }
383 }
384
385 // Set labels and put in graph.
386 for (auto& kv : time_series) {
387 kv.second.label = SsrcToString(kv.first);
388 kv.second.style = BAR_GRAPH;
389 plot->series.push_back(std::move(kv.second));
390 }
391
392 plot->xaxis_min = kDefaultXMin;
393 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
394 plot->xaxis_label = "Time (s)";
395 plot->yaxis_min = kDefaultYMin;
396 plot->yaxis_max = max_y * kYMargin;
397 plot->yaxis_label = "Time since last playout (ms)";
398 plot->title = "Audio playout";
399}
400
401// For each SSRC, plot the time between the consecutive playouts.
402void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
403 std::map<uint32_t, TimeSeries> time_series;
404 std::map<uint32_t, uint16_t> last_seqno;
405
406 PacketDirection direction;
407 MediaType media_type;
408 uint8_t header[IP_PACKET_SIZE];
409 size_t header_length, total_length;
410
411 int max_y = 1;
412 int min_y = 0;
413
414 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
415 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
416 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
417 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
418 &header_length, &total_length);
419 uint64_t timestamp = parsed_log_.GetTimestamp(i);
420 if (direction == PacketDirection::kIncomingPacket) {
421 // Parse header to get SSRC.
422 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
423 RTPHeader parsed_header;
424 rtp_parser.Parse(&parsed_header);
425 // Filter on SSRC.
426 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
427 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
428 int y = WrappingDifference(parsed_header.sequenceNumber,
429 last_seqno[parsed_header.ssrc], 1ul << 16);
430 if (time_series[parsed_header.ssrc].points.size() == 0) {
431 // There were no previusly logged playout for this SSRC.
432 // Generate a point, but place it on the x-axis.
433 y = 0;
434 }
435 max_y = std::max(max_y, y);
436 min_y = std::min(min_y, y);
437 time_series[parsed_header.ssrc].points.push_back(
438 TimeSeriesPoint(x, y));
439 last_seqno[parsed_header.ssrc] = parsed_header.sequenceNumber;
440 }
441 }
442 }
443 }
444
445 // Set labels and put in graph.
446 for (auto& kv : time_series) {
447 kv.second.label = SsrcToString(kv.first);
448 kv.second.style = BAR_GRAPH;
449 plot->series.push_back(std::move(kv.second));
450 }
451
452 plot->xaxis_min = kDefaultXMin;
453 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
454 plot->xaxis_label = "Time (s)";
455 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
456 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
457 plot->yaxis_label = "Difference since last packet";
458 plot->title = "Sequence number";
459}
460
461void EventLogAnalyzer::CreateDelayChangeGraph(Plot* plot) {
terelius54ce6802016-07-13 06:44:41 -0700462 double max_y = 10;
463 double min_y = 0;
464
terelius88e64e52016-07-19 01:51:06 -0700465 for (auto& kv : rtp_packets_) {
466 StreamId stream_id = kv.first;
467 // Filter on direction and SSRC.
468 if (stream_id.GetDirection() != kIncomingPacket ||
469 !MatchingSsrc(stream_id.GetSsrc(), desired_ssrc_)) {
470 continue;
471 }
terelius54ce6802016-07-13 06:44:41 -0700472
terelius88e64e52016-07-19 01:51:06 -0700473 TimeSeries time_series;
474 time_series.label = SsrcToString(stream_id.GetSsrc());
475 time_series.style = BAR_GRAPH;
476 const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
477 int64_t last_abs_send_time = 0;
478 int64_t last_timestamp = 0;
479 for (const LoggedRtpPacket& packet : packet_stream) {
480 if (packet.header.extension.hasAbsoluteSendTime) {
481 int64_t send_time_diff =
482 WrappingDifference(packet.header.extension.absoluteSendTime,
483 last_abs_send_time, 1ul << 24);
484 int64_t recv_time_diff = packet.timestamp - last_timestamp;
485
486 last_abs_send_time = packet.header.extension.absoluteSendTime;
487 last_timestamp = packet.timestamp;
488
489 float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
490 double y =
491 static_cast<double>(recv_time_diff -
492 AbsSendTimeToMicroseconds(send_time_diff)) /
493 1000;
494 if (time_series.points.size() == 0) {
495 // There were no previously logged packets for this SSRC.
496 // Generate a point, but place it on the x-axis.
497 y = 0;
terelius54ce6802016-07-13 06:44:41 -0700498 }
terelius88e64e52016-07-19 01:51:06 -0700499 max_y = std::max(max_y, y);
500 min_y = std::min(min_y, y);
501 time_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700502 }
503 }
terelius88e64e52016-07-19 01:51:06 -0700504 // Add the data set to the plot.
505 plot->series.push_back(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700506 }
507
508 plot->xaxis_min = kDefaultXMin;
509 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
510 plot->xaxis_label = "Time (s)";
511 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
512 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
513 plot->yaxis_label = "Latency change (ms)";
514 plot->title = "Network latency change between consecutive packets";
515}
516
517void EventLogAnalyzer::CreateAccumulatedDelayChangeGraph(Plot* plot) {
terelius54ce6802016-07-13 06:44:41 -0700518 double max_y = 10;
519 double min_y = 0;
520
terelius88e64e52016-07-19 01:51:06 -0700521 for (auto& kv : rtp_packets_) {
522 StreamId stream_id = kv.first;
523 // Filter on direction and SSRC.
524 if (stream_id.GetDirection() != kIncomingPacket ||
525 !MatchingSsrc(stream_id.GetSsrc(), desired_ssrc_)) {
526 continue;
527 }
528 TimeSeries time_series;
529 time_series.label = SsrcToString(stream_id.GetSsrc());
530 time_series.style = LINE_GRAPH;
531 const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
532 int64_t last_abs_send_time = 0;
533 int64_t last_timestamp = 0;
534 double accumulated_delay_ms = 0;
535 for (const LoggedRtpPacket& packet : packet_stream) {
536 if (packet.header.extension.hasAbsoluteSendTime) {
537 int64_t send_time_diff =
538 WrappingDifference(packet.header.extension.absoluteSendTime,
539 last_abs_send_time, 1ul << 24);
540 int64_t recv_time_diff = packet.timestamp - last_timestamp;
terelius54ce6802016-07-13 06:44:41 -0700541
terelius88e64e52016-07-19 01:51:06 -0700542 last_abs_send_time = packet.header.extension.absoluteSendTime;
543 last_timestamp = packet.timestamp;
544
545 float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
546 accumulated_delay_ms +=
547 static_cast<double>(recv_time_diff -
548 AbsSendTimeToMicroseconds(send_time_diff)) /
549 1000;
550 if (time_series.points.size() == 0) {
551 // There were no previously logged packets for this SSRC.
552 // Generate a point, but place it on the x-axis.
553 accumulated_delay_ms = 0;
terelius54ce6802016-07-13 06:44:41 -0700554 }
terelius88e64e52016-07-19 01:51:06 -0700555 max_y = std::max(max_y, accumulated_delay_ms);
556 min_y = std::min(min_y, accumulated_delay_ms);
557 time_series.points.emplace_back(x, accumulated_delay_ms);
terelius54ce6802016-07-13 06:44:41 -0700558 }
559 }
terelius88e64e52016-07-19 01:51:06 -0700560 // Add the data set to the plot.
561 plot->series.push_back(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700562 }
563
564 plot->xaxis_min = kDefaultXMin;
565 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
566 plot->xaxis_label = "Time (s)";
567 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
568 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
569 plot->yaxis_label = "Latency change (ms)";
570 plot->title = "Accumulated network latency change";
571}
572
573// Plot the total bandwidth used by all RTP streams.
574void EventLogAnalyzer::CreateTotalBitrateGraph(
575 PacketDirection desired_direction,
576 Plot* plot) {
577 struct TimestampSize {
578 TimestampSize(uint64_t t, size_t s) : timestamp(t), size(s) {}
579 uint64_t timestamp;
580 size_t size;
581 };
582 std::vector<TimestampSize> packets;
583
584 PacketDirection direction;
585 size_t total_length;
586
587 // Extract timestamps and sizes for the relevant packets.
588 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
589 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
590 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
591 parsed_log_.GetRtpHeader(i, &direction, nullptr, nullptr, nullptr,
592 &total_length);
593 if (direction == desired_direction) {
594 uint64_t timestamp = parsed_log_.GetTimestamp(i);
595 packets.push_back(TimestampSize(timestamp, total_length));
596 }
597 }
598 }
599
600 size_t window_index_begin = 0;
601 size_t window_index_end = 0;
602 size_t bytes_in_window = 0;
603 float max_y = 0;
604
605 // Calculate a moving average of the bitrate and store in a TimeSeries.
606 plot->series.push_back(TimeSeries());
607 for (uint64_t time = begin_time_; time < end_time_ + step_; time += step_) {
608 while (window_index_end < packets.size() &&
609 packets[window_index_end].timestamp < time) {
610 bytes_in_window += packets[window_index_end].size;
611 window_index_end++;
612 }
613 while (window_index_begin < packets.size() &&
614 packets[window_index_begin].timestamp < time - window_duration_) {
615 RTC_DCHECK_LE(packets[window_index_begin].size, bytes_in_window);
616 bytes_in_window -= packets[window_index_begin].size;
617 window_index_begin++;
618 }
619 float window_duration_in_seconds =
620 static_cast<float>(window_duration_) / 1000000;
621 float x = static_cast<float>(time - begin_time_) / 1000000;
622 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
623 max_y = std::max(max_y, y);
624 plot->series.back().points.push_back(TimeSeriesPoint(x, y));
625 }
626
627 // Set labels.
628 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
629 plot->series.back().label = "Incoming bitrate";
630 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
631 plot->series.back().label = "Outgoing bitrate";
632 }
633 plot->series.back().style = LINE_GRAPH;
634
terelius8058e582016-07-25 01:32:41 -0700635 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
636 if (desired_direction == kOutgoingPacket) {
637 plot->series.push_back(TimeSeries());
638 for (auto& bwe_update : bwe_loss_updates_) {
639 float x =
640 static_cast<float>(bwe_update.timestamp - begin_time_) / 1000000;
641 float y = static_cast<float>(bwe_update.new_bitrate) / 1000;
642 max_y = std::max(max_y, y);
643 plot->series.back().points.emplace_back(x, y);
644 }
645 plot->series.back().label = "Loss-based estimate";
646 plot->series.back().style = LINE_GRAPH;
647 }
648
terelius54ce6802016-07-13 06:44:41 -0700649 plot->xaxis_min = kDefaultXMin;
650 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
651 plot->xaxis_label = "Time (s)";
652 plot->yaxis_min = kDefaultYMin;
653 plot->yaxis_max = max_y * kYMargin;
654 plot->yaxis_label = "Bitrate (kbps)";
655 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
656 plot->title = "Incoming RTP bitrate";
657 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
658 plot->title = "Outgoing RTP bitrate";
659 }
660}
661
662// For each SSRC, plot the bandwidth used by that stream.
663void EventLogAnalyzer::CreateStreamBitrateGraph(
664 PacketDirection desired_direction,
665 Plot* plot) {
666 struct TimestampSize {
667 TimestampSize(uint64_t t, size_t s) : timestamp(t), size(s) {}
668 uint64_t timestamp;
669 size_t size;
670 };
terelius88e64e52016-07-19 01:51:06 -0700671 std::map<uint32_t, std::vector<TimestampSize>> packets;
terelius54ce6802016-07-13 06:44:41 -0700672
673 PacketDirection direction;
674 MediaType media_type;
675 uint8_t header[IP_PACKET_SIZE];
676 size_t header_length, total_length;
677
678 // Extract timestamps and sizes for the relevant packets.
679 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
680 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
681 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
682 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
683 &header_length, &total_length);
684 if (direction == desired_direction) {
685 // Parse header to get SSRC.
686 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
687 RTPHeader parsed_header;
688 rtp_parser.Parse(&parsed_header);
689 // Filter on SSRC.
690 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
691 uint64_t timestamp = parsed_log_.GetTimestamp(i);
692 packets[parsed_header.ssrc].push_back(
693 TimestampSize(timestamp, total_length));
694 }
695 }
696 }
697 }
698
699 float max_y = 0;
700
701 for (auto& kv : packets) {
702 size_t window_index_begin = 0;
703 size_t window_index_end = 0;
704 size_t bytes_in_window = 0;
705
706 // Calculate a moving average of the bitrate and store in a TimeSeries.
707 plot->series.push_back(TimeSeries());
708 for (uint64_t time = begin_time_; time < end_time_ + step_; time += step_) {
709 while (window_index_end < kv.second.size() &&
710 kv.second[window_index_end].timestamp < time) {
711 bytes_in_window += kv.second[window_index_end].size;
712 window_index_end++;
713 }
714 while (window_index_begin < kv.second.size() &&
715 kv.second[window_index_begin].timestamp <
716 time - window_duration_) {
717 RTC_DCHECK_LE(kv.second[window_index_begin].size, bytes_in_window);
718 bytes_in_window -= kv.second[window_index_begin].size;
719 window_index_begin++;
720 }
721 float window_duration_in_seconds =
722 static_cast<float>(window_duration_) / 1000000;
723 float x = static_cast<float>(time - begin_time_) / 1000000;
724 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
725 max_y = std::max(max_y, y);
726 plot->series.back().points.push_back(TimeSeriesPoint(x, y));
727 }
728
729 // Set labels.
730 plot->series.back().label = SsrcToString(kv.first);
731 plot->series.back().style = LINE_GRAPH;
732 }
733
734 plot->xaxis_min = kDefaultXMin;
735 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
736 plot->xaxis_label = "Time (s)";
737 plot->yaxis_min = kDefaultYMin;
738 plot->yaxis_max = max_y * kYMargin;
739 plot->yaxis_label = "Bitrate (kbps)";
740 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
741 plot->title = "Incoming bitrate per stream";
742 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
743 plot->title = "Outgoing bitrate per stream";
744 }
745}
746
Stefan Holmer13181032016-07-29 14:48:54 +0200747void EventLogAnalyzer::CreateBweGraph(Plot* plot) {
748 std::map<uint64_t, const LoggedRtpPacket*> outgoing_rtp;
749 std::map<uint64_t, const LoggedRtcpPacket*> incoming_rtcp;
750
751 for (const auto& kv : rtp_packets_) {
752 if (kv.first.GetDirection() == PacketDirection::kOutgoingPacket) {
753 for (const LoggedRtpPacket& rtp_packet : kv.second)
754 outgoing_rtp.insert(std::make_pair(rtp_packet.timestamp, &rtp_packet));
755 }
756 }
757
758 for (const auto& kv : rtcp_packets_) {
759 if (kv.first.GetDirection() == PacketDirection::kIncomingPacket) {
760 for (const LoggedRtcpPacket& rtcp_packet : kv.second)
761 incoming_rtcp.insert(
762 std::make_pair(rtcp_packet.timestamp, &rtcp_packet));
763 }
764 }
765
766 SimulatedClock clock(0);
767 BitrateObserver observer;
768 RtcEventLogNullImpl null_event_log;
769 CongestionController cc(&clock, &observer, &observer, &null_event_log);
770 // TODO(holmer): Log the call config and use that here instead.
771 static const uint32_t kDefaultStartBitrateBps = 300000;
772 cc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
773
774 TimeSeries time_series;
775 time_series.label = "BWE";
776 time_series.style = LINE_DOT_GRAPH;
777 uint32_t max_y = 10;
778 uint32_t min_y = 0;
779
780 auto rtp_iterator = outgoing_rtp.begin();
781 auto rtcp_iterator = incoming_rtcp.begin();
782
783 auto NextRtpTime = [&]() {
784 if (rtp_iterator != outgoing_rtp.end())
785 return static_cast<int64_t>(rtp_iterator->first);
786 return std::numeric_limits<int64_t>::max();
787 };
788
789 auto NextRtcpTime = [&]() {
790 if (rtcp_iterator != incoming_rtcp.end())
791 return static_cast<int64_t>(rtcp_iterator->first);
792 return std::numeric_limits<int64_t>::max();
793 };
794
795 auto NextProcessTime = [&]() {
796 if (rtcp_iterator != incoming_rtcp.end() ||
797 rtp_iterator != outgoing_rtp.end()) {
798 return clock.TimeInMicroseconds() +
799 std::max<int64_t>(cc.TimeUntilNextProcess() * 1000, 0);
800 }
801 return std::numeric_limits<int64_t>::max();
802 };
803
804 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
805 while (time_us != std::numeric_limits<int64_t>::max()) {
806 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
807 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
808 clock.AdvanceTimeMilliseconds(rtcp_iterator->first / 1000 -
809 clock.TimeInMilliseconds());
810 const LoggedRtcpPacket& rtcp = *rtcp_iterator->second;
811 if (rtcp.type == kRtcpTransportFeedback) {
812 cc.GetTransportFeedbackObserver()->OnTransportFeedback(
813 *static_cast<rtcp::TransportFeedback*>(rtcp.packet.get()));
814 }
815 ++rtcp_iterator;
816 }
817 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
818 clock.AdvanceTimeMilliseconds(rtp_iterator->first / 1000 -
819 clock.TimeInMilliseconds());
820 const LoggedRtpPacket& rtp = *rtp_iterator->second;
821 if (rtp.header.extension.hasTransportSequenceNumber) {
822 RTC_DCHECK(rtp.header.extension.hasTransportSequenceNumber);
823 cc.GetTransportFeedbackObserver()->AddPacket(
824 rtp.header.extension.transportSequenceNumber, rtp.total_length, 0);
825 rtc::SentPacket sent_packet(
826 rtp.header.extension.transportSequenceNumber, rtp.timestamp / 1000);
827 cc.OnSentPacket(sent_packet);
828 }
829 ++rtp_iterator;
830 }
831 if (clock.TimeInMicroseconds() >= NextProcessTime())
832 cc.Process();
833 if (observer.GetAndResetBitrateUpdated()) {
834 uint32_t y = observer.last_bitrate_bps() / 1000;
835 max_y = std::max(max_y, y);
836 min_y = std::min(min_y, y);
837 float x = static_cast<float>(clock.TimeInMicroseconds() - begin_time_) /
838 1000000;
839 time_series.points.emplace_back(x, y);
840 }
841 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
842 }
843 // Add the data set to the plot.
844 plot->series.push_back(std::move(time_series));
845
846 plot->xaxis_min = kDefaultXMin;
847 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
848 plot->xaxis_label = "Time (s)";
849 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
850 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
851 plot->yaxis_label = "Bitrate (kbps)";
852 plot->title = "BWE";
853}
854
terelius54ce6802016-07-13 06:44:41 -0700855} // namespace plotting
856} // namespace webrtc