blob: ba92da7ad6f1cfdd01b44c22798c79cfeb43eb55 [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 &&
terelius88c1d2b2016-08-01 05:20:33 -0700140 event_type != ParsedRtcEventLog::AUDIO_SENDER_CONFIG_EVENT &&
141 event_type != ParsedRtcEventLog::LOG_START &&
142 event_type != ParsedRtcEventLog::LOG_END) {
terelius88e64e52016-07-19 01:51:06 -0700143 uint64_t timestamp = parsed_log_.GetTimestamp(i);
144 first_timestamp = std::min(first_timestamp, timestamp);
145 last_timestamp = std::max(last_timestamp, timestamp);
146 }
147
148 switch (parsed_log_.GetEventType(i)) {
149 case ParsedRtcEventLog::VIDEO_RECEIVER_CONFIG_EVENT: {
150 VideoReceiveStream::Config config(nullptr);
151 parsed_log_.GetVideoReceiveConfig(i, &config);
Stefan Holmer13181032016-07-29 14:48:54 +0200152 StreamId stream(config.rtp.remote_ssrc, kIncomingPacket);
stefan6a850c32016-07-29 10:28:08 -0700153 RegisterHeaderExtensions(config.rtp.extensions,
154 &extension_maps[stream]);
155 for (auto kv : config.rtp.rtx) {
156 StreamId rtx_stream(kv.second.ssrc, kIncomingPacket);
157 RegisterHeaderExtensions(config.rtp.extensions,
158 &extension_maps[rtx_stream]);
terelius88e64e52016-07-19 01:51:06 -0700159 }
160 break;
161 }
162 case ParsedRtcEventLog::VIDEO_SENDER_CONFIG_EVENT: {
163 VideoSendStream::Config config(nullptr);
164 parsed_log_.GetVideoSendConfig(i, &config);
165 for (auto ssrc : config.rtp.ssrcs) {
Stefan Holmer13181032016-07-29 14:48:54 +0200166 StreamId stream(ssrc, kOutgoingPacket);
stefan6a850c32016-07-29 10:28:08 -0700167 RegisterHeaderExtensions(config.rtp.extensions,
168 &extension_maps[stream]);
169 }
170 for (auto ssrc : config.rtp.rtx.ssrcs) {
171 StreamId stream(ssrc, kOutgoingPacket);
172 RegisterHeaderExtensions(config.rtp.extensions,
173 &extension_maps[stream]);
terelius88e64e52016-07-19 01:51:06 -0700174 }
175 break;
176 }
177 case ParsedRtcEventLog::AUDIO_RECEIVER_CONFIG_EVENT: {
178 AudioReceiveStream::Config config;
179 // TODO(terelius): Parse the audio configs once we have them.
180 break;
181 }
182 case ParsedRtcEventLog::AUDIO_SENDER_CONFIG_EVENT: {
183 AudioSendStream::Config config(nullptr);
184 // TODO(terelius): Parse the audio configs once we have them.
185 break;
186 }
187 case ParsedRtcEventLog::RTP_EVENT: {
Stefan Holmer13181032016-07-29 14:48:54 +0200188 MediaType media_type;
terelius88e64e52016-07-19 01:51:06 -0700189 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
190 &header_length, &total_length);
191 // Parse header to get SSRC.
192 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
193 RTPHeader parsed_header;
194 rtp_parser.Parse(&parsed_header);
Stefan Holmer13181032016-07-29 14:48:54 +0200195 StreamId stream(parsed_header.ssrc, direction);
terelius88e64e52016-07-19 01:51:06 -0700196 // Look up the extension_map and parse it again to get the extensions.
197 if (extension_maps.count(stream) == 1) {
198 RtpHeaderExtensionMap* extension_map = &extension_maps[stream];
199 rtp_parser.Parse(&parsed_header, extension_map);
200 }
201 uint64_t timestamp = parsed_log_.GetTimestamp(i);
202 rtp_packets_[stream].push_back(
Stefan Holmer13181032016-07-29 14:48:54 +0200203 LoggedRtpPacket(timestamp, parsed_header, total_length));
terelius88e64e52016-07-19 01:51:06 -0700204 break;
205 }
206 case ParsedRtcEventLog::RTCP_EVENT: {
Stefan Holmer13181032016-07-29 14:48:54 +0200207 uint8_t packet[IP_PACKET_SIZE];
208 MediaType media_type;
209 parsed_log_.GetRtcpPacket(i, &direction, &media_type, packet,
210 &total_length);
211
212 RtpUtility::RtpHeaderParser rtp_parser(packet, total_length);
213 RTPHeader parsed_header;
214 RTC_CHECK(rtp_parser.ParseRtcp(&parsed_header));
215 uint32_t ssrc = parsed_header.ssrc;
216
217 RTCPUtility::RTCPParserV2 rtcp_parser(packet, total_length, true);
218 RTC_CHECK(rtcp_parser.IsValid());
219
220 RTCPUtility::RTCPPacketTypes packet_type = rtcp_parser.Begin();
221 while (packet_type != RTCPUtility::RTCPPacketTypes::kInvalid) {
222 switch (packet_type) {
223 case RTCPUtility::RTCPPacketTypes::kTransportFeedback: {
224 // Currently feedback is logged twice, both for audio and video.
225 // Only act on one of them.
226 if (media_type == MediaType::VIDEO) {
227 std::unique_ptr<rtcp::RtcpPacket> rtcp_packet(
228 rtcp_parser.ReleaseRtcpPacket());
229 StreamId stream(ssrc, direction);
230 uint64_t timestamp = parsed_log_.GetTimestamp(i);
231 rtcp_packets_[stream].push_back(LoggedRtcpPacket(
232 timestamp, kRtcpTransportFeedback, std::move(rtcp_packet)));
233 }
234 break;
235 }
236 default:
237 break;
238 }
239 rtcp_parser.Iterate();
240 packet_type = rtcp_parser.PacketType();
241 }
terelius88e64e52016-07-19 01:51:06 -0700242 break;
243 }
244 case ParsedRtcEventLog::LOG_START: {
245 break;
246 }
247 case ParsedRtcEventLog::LOG_END: {
248 break;
249 }
250 case ParsedRtcEventLog::BWE_PACKET_LOSS_EVENT: {
terelius8058e582016-07-25 01:32:41 -0700251 BwePacketLossEvent bwe_update;
252 bwe_update.timestamp = parsed_log_.GetTimestamp(i);
253 parsed_log_.GetBwePacketLossEvent(i, &bwe_update.new_bitrate,
254 &bwe_update.fraction_loss,
255 &bwe_update.expected_packets);
256 bwe_loss_updates_.push_back(bwe_update);
terelius88e64e52016-07-19 01:51:06 -0700257 break;
258 }
259 case ParsedRtcEventLog::BWE_PACKET_DELAY_EVENT: {
260 break;
261 }
262 case ParsedRtcEventLog::AUDIO_PLAYOUT_EVENT: {
263 break;
264 }
265 case ParsedRtcEventLog::UNKNOWN_EVENT: {
266 break;
267 }
268 }
terelius54ce6802016-07-13 06:44:41 -0700269 }
terelius88e64e52016-07-19 01:51:06 -0700270
terelius54ce6802016-07-13 06:44:41 -0700271 if (last_timestamp < first_timestamp) {
272 // No useful events in the log.
273 first_timestamp = last_timestamp = 0;
274 }
275 begin_time_ = first_timestamp;
276 end_time_ = last_timestamp;
277}
278
Stefan Holmer13181032016-07-29 14:48:54 +0200279class BitrateObserver : public CongestionController::Observer,
280 public RemoteBitrateObserver {
281 public:
282 BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
283
284 void OnNetworkChanged(uint32_t bitrate_bps,
285 uint8_t fraction_loss,
286 int64_t rtt_ms) override {
287 last_bitrate_bps_ = bitrate_bps;
288 bitrate_updated_ = true;
289 }
290
291 void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
292 uint32_t bitrate) override {}
293
294 uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
295 bool GetAndResetBitrateUpdated() {
296 bool bitrate_updated = bitrate_updated_;
297 bitrate_updated_ = false;
298 return bitrate_updated;
299 }
300
301 private:
302 uint32_t last_bitrate_bps_;
303 bool bitrate_updated_;
304};
305
terelius54ce6802016-07-13 06:44:41 -0700306void EventLogAnalyzer::CreatePacketGraph(PacketDirection desired_direction,
307 Plot* plot) {
308 std::map<uint32_t, TimeSeries> time_series;
309
310 PacketDirection direction;
311 MediaType media_type;
312 uint8_t header[IP_PACKET_SIZE];
313 size_t header_length, total_length;
314 float max_y = 0;
315
316 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
317 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
318 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
319 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
320 &header_length, &total_length);
321 if (direction == desired_direction) {
322 // Parse header to get SSRC.
323 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
324 RTPHeader parsed_header;
325 rtp_parser.Parse(&parsed_header);
326 // Filter on SSRC.
327 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
328 uint64_t timestamp = parsed_log_.GetTimestamp(i);
329 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
330 float y = total_length;
331 max_y = std::max(max_y, y);
332 time_series[parsed_header.ssrc].points.push_back(
333 TimeSeriesPoint(x, y));
334 }
335 }
336 }
337 }
338
339 // Set labels and put in graph.
340 for (auto& kv : time_series) {
341 kv.second.label = SsrcToString(kv.first);
342 kv.second.style = BAR_GRAPH;
343 plot->series.push_back(std::move(kv.second));
344 }
345
346 plot->xaxis_min = kDefaultXMin;
347 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
348 plot->xaxis_label = "Time (s)";
349 plot->yaxis_min = kDefaultYMin;
350 plot->yaxis_max = max_y * kYMargin;
351 plot->yaxis_label = "Packet size (bytes)";
352 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
353 plot->title = "Incoming RTP packets";
354 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
355 plot->title = "Outgoing RTP packets";
356 }
357}
358
359// For each SSRC, plot the time between the consecutive playouts.
360void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
361 std::map<uint32_t, TimeSeries> time_series;
362 std::map<uint32_t, uint64_t> last_playout;
363
364 uint32_t ssrc;
365 float max_y = 0;
366
367 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
368 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
369 if (event_type == ParsedRtcEventLog::AUDIO_PLAYOUT_EVENT) {
370 parsed_log_.GetAudioPlayout(i, &ssrc);
371 uint64_t timestamp = parsed_log_.GetTimestamp(i);
372 if (MatchingSsrc(ssrc, desired_ssrc_)) {
373 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
374 float y = static_cast<float>(timestamp - last_playout[ssrc]) / 1000;
375 if (time_series[ssrc].points.size() == 0) {
376 // There were no previusly logged playout for this SSRC.
377 // Generate a point, but place it on the x-axis.
378 y = 0;
379 }
380 max_y = std::max(max_y, y);
381 time_series[ssrc].points.push_back(TimeSeriesPoint(x, y));
382 last_playout[ssrc] = timestamp;
383 }
384 }
385 }
386
387 // Set labels and put in graph.
388 for (auto& kv : time_series) {
389 kv.second.label = SsrcToString(kv.first);
390 kv.second.style = BAR_GRAPH;
391 plot->series.push_back(std::move(kv.second));
392 }
393
394 plot->xaxis_min = kDefaultXMin;
395 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
396 plot->xaxis_label = "Time (s)";
397 plot->yaxis_min = kDefaultYMin;
398 plot->yaxis_max = max_y * kYMargin;
399 plot->yaxis_label = "Time since last playout (ms)";
400 plot->title = "Audio playout";
401}
402
403// For each SSRC, plot the time between the consecutive playouts.
404void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
405 std::map<uint32_t, TimeSeries> time_series;
406 std::map<uint32_t, uint16_t> last_seqno;
407
408 PacketDirection direction;
409 MediaType media_type;
410 uint8_t header[IP_PACKET_SIZE];
411 size_t header_length, total_length;
412
413 int max_y = 1;
414 int min_y = 0;
415
416 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
417 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
418 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
419 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
420 &header_length, &total_length);
421 uint64_t timestamp = parsed_log_.GetTimestamp(i);
422 if (direction == PacketDirection::kIncomingPacket) {
423 // Parse header to get SSRC.
424 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
425 RTPHeader parsed_header;
426 rtp_parser.Parse(&parsed_header);
427 // Filter on SSRC.
428 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
429 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
430 int y = WrappingDifference(parsed_header.sequenceNumber,
431 last_seqno[parsed_header.ssrc], 1ul << 16);
432 if (time_series[parsed_header.ssrc].points.size() == 0) {
433 // There were no previusly logged playout for this SSRC.
434 // Generate a point, but place it on the x-axis.
435 y = 0;
436 }
437 max_y = std::max(max_y, y);
438 min_y = std::min(min_y, y);
439 time_series[parsed_header.ssrc].points.push_back(
440 TimeSeriesPoint(x, y));
441 last_seqno[parsed_header.ssrc] = parsed_header.sequenceNumber;
442 }
443 }
444 }
445 }
446
447 // Set labels and put in graph.
448 for (auto& kv : time_series) {
449 kv.second.label = SsrcToString(kv.first);
450 kv.second.style = BAR_GRAPH;
451 plot->series.push_back(std::move(kv.second));
452 }
453
454 plot->xaxis_min = kDefaultXMin;
455 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
456 plot->xaxis_label = "Time (s)";
457 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
458 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
459 plot->yaxis_label = "Difference since last packet";
460 plot->title = "Sequence number";
461}
462
463void EventLogAnalyzer::CreateDelayChangeGraph(Plot* plot) {
terelius54ce6802016-07-13 06:44:41 -0700464 double max_y = 10;
465 double min_y = 0;
466
terelius88e64e52016-07-19 01:51:06 -0700467 for (auto& kv : rtp_packets_) {
468 StreamId stream_id = kv.first;
469 // Filter on direction and SSRC.
470 if (stream_id.GetDirection() != kIncomingPacket ||
471 !MatchingSsrc(stream_id.GetSsrc(), desired_ssrc_)) {
472 continue;
473 }
terelius54ce6802016-07-13 06:44:41 -0700474
terelius88e64e52016-07-19 01:51:06 -0700475 TimeSeries time_series;
476 time_series.label = SsrcToString(stream_id.GetSsrc());
477 time_series.style = BAR_GRAPH;
478 const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
479 int64_t last_abs_send_time = 0;
480 int64_t last_timestamp = 0;
481 for (const LoggedRtpPacket& packet : packet_stream) {
482 if (packet.header.extension.hasAbsoluteSendTime) {
483 int64_t send_time_diff =
484 WrappingDifference(packet.header.extension.absoluteSendTime,
485 last_abs_send_time, 1ul << 24);
486 int64_t recv_time_diff = packet.timestamp - last_timestamp;
487
488 last_abs_send_time = packet.header.extension.absoluteSendTime;
489 last_timestamp = packet.timestamp;
490
491 float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
492 double y =
493 static_cast<double>(recv_time_diff -
494 AbsSendTimeToMicroseconds(send_time_diff)) /
495 1000;
496 if (time_series.points.size() == 0) {
497 // There were no previously logged packets for this SSRC.
498 // Generate a point, but place it on the x-axis.
499 y = 0;
terelius54ce6802016-07-13 06:44:41 -0700500 }
terelius88e64e52016-07-19 01:51:06 -0700501 max_y = std::max(max_y, y);
502 min_y = std::min(min_y, y);
503 time_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700504 }
505 }
terelius88e64e52016-07-19 01:51:06 -0700506 // Add the data set to the plot.
507 plot->series.push_back(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700508 }
509
510 plot->xaxis_min = kDefaultXMin;
511 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
512 plot->xaxis_label = "Time (s)";
513 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
514 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
515 plot->yaxis_label = "Latency change (ms)";
516 plot->title = "Network latency change between consecutive packets";
517}
518
519void EventLogAnalyzer::CreateAccumulatedDelayChangeGraph(Plot* plot) {
terelius54ce6802016-07-13 06:44:41 -0700520 double max_y = 10;
521 double min_y = 0;
522
terelius88e64e52016-07-19 01:51:06 -0700523 for (auto& kv : rtp_packets_) {
524 StreamId stream_id = kv.first;
525 // Filter on direction and SSRC.
526 if (stream_id.GetDirection() != kIncomingPacket ||
527 !MatchingSsrc(stream_id.GetSsrc(), desired_ssrc_)) {
528 continue;
529 }
530 TimeSeries time_series;
531 time_series.label = SsrcToString(stream_id.GetSsrc());
532 time_series.style = LINE_GRAPH;
533 const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
534 int64_t last_abs_send_time = 0;
535 int64_t last_timestamp = 0;
536 double accumulated_delay_ms = 0;
537 for (const LoggedRtpPacket& packet : packet_stream) {
538 if (packet.header.extension.hasAbsoluteSendTime) {
539 int64_t send_time_diff =
540 WrappingDifference(packet.header.extension.absoluteSendTime,
541 last_abs_send_time, 1ul << 24);
542 int64_t recv_time_diff = packet.timestamp - last_timestamp;
terelius54ce6802016-07-13 06:44:41 -0700543
terelius88e64e52016-07-19 01:51:06 -0700544 last_abs_send_time = packet.header.extension.absoluteSendTime;
545 last_timestamp = packet.timestamp;
546
547 float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
548 accumulated_delay_ms +=
549 static_cast<double>(recv_time_diff -
550 AbsSendTimeToMicroseconds(send_time_diff)) /
551 1000;
552 if (time_series.points.size() == 0) {
553 // There were no previously logged packets for this SSRC.
554 // Generate a point, but place it on the x-axis.
555 accumulated_delay_ms = 0;
terelius54ce6802016-07-13 06:44:41 -0700556 }
terelius88e64e52016-07-19 01:51:06 -0700557 max_y = std::max(max_y, accumulated_delay_ms);
558 min_y = std::min(min_y, accumulated_delay_ms);
559 time_series.points.emplace_back(x, accumulated_delay_ms);
terelius54ce6802016-07-13 06:44:41 -0700560 }
561 }
terelius88e64e52016-07-19 01:51:06 -0700562 // Add the data set to the plot.
563 plot->series.push_back(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700564 }
565
566 plot->xaxis_min = kDefaultXMin;
567 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
568 plot->xaxis_label = "Time (s)";
569 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
570 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
571 plot->yaxis_label = "Latency change (ms)";
572 plot->title = "Accumulated network latency change";
573}
574
575// Plot the total bandwidth used by all RTP streams.
576void EventLogAnalyzer::CreateTotalBitrateGraph(
577 PacketDirection desired_direction,
578 Plot* plot) {
579 struct TimestampSize {
580 TimestampSize(uint64_t t, size_t s) : timestamp(t), size(s) {}
581 uint64_t timestamp;
582 size_t size;
583 };
584 std::vector<TimestampSize> packets;
585
586 PacketDirection direction;
587 size_t total_length;
588
589 // Extract timestamps and sizes for the relevant packets.
590 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
591 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
592 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
593 parsed_log_.GetRtpHeader(i, &direction, nullptr, nullptr, nullptr,
594 &total_length);
595 if (direction == desired_direction) {
596 uint64_t timestamp = parsed_log_.GetTimestamp(i);
597 packets.push_back(TimestampSize(timestamp, total_length));
598 }
599 }
600 }
601
602 size_t window_index_begin = 0;
603 size_t window_index_end = 0;
604 size_t bytes_in_window = 0;
605 float max_y = 0;
606
607 // Calculate a moving average of the bitrate and store in a TimeSeries.
608 plot->series.push_back(TimeSeries());
609 for (uint64_t time = begin_time_; time < end_time_ + step_; time += step_) {
610 while (window_index_end < packets.size() &&
611 packets[window_index_end].timestamp < time) {
612 bytes_in_window += packets[window_index_end].size;
613 window_index_end++;
614 }
615 while (window_index_begin < packets.size() &&
616 packets[window_index_begin].timestamp < time - window_duration_) {
617 RTC_DCHECK_LE(packets[window_index_begin].size, bytes_in_window);
618 bytes_in_window -= packets[window_index_begin].size;
619 window_index_begin++;
620 }
621 float window_duration_in_seconds =
622 static_cast<float>(window_duration_) / 1000000;
623 float x = static_cast<float>(time - begin_time_) / 1000000;
624 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
625 max_y = std::max(max_y, y);
626 plot->series.back().points.push_back(TimeSeriesPoint(x, y));
627 }
628
629 // Set labels.
630 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
631 plot->series.back().label = "Incoming bitrate";
632 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
633 plot->series.back().label = "Outgoing bitrate";
634 }
635 plot->series.back().style = LINE_GRAPH;
636
terelius8058e582016-07-25 01:32:41 -0700637 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
638 if (desired_direction == kOutgoingPacket) {
639 plot->series.push_back(TimeSeries());
640 for (auto& bwe_update : bwe_loss_updates_) {
641 float x =
642 static_cast<float>(bwe_update.timestamp - begin_time_) / 1000000;
643 float y = static_cast<float>(bwe_update.new_bitrate) / 1000;
644 max_y = std::max(max_y, y);
645 plot->series.back().points.emplace_back(x, y);
646 }
647 plot->series.back().label = "Loss-based estimate";
648 plot->series.back().style = LINE_GRAPH;
649 }
650
terelius54ce6802016-07-13 06:44:41 -0700651 plot->xaxis_min = kDefaultXMin;
652 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
653 plot->xaxis_label = "Time (s)";
654 plot->yaxis_min = kDefaultYMin;
655 plot->yaxis_max = max_y * kYMargin;
656 plot->yaxis_label = "Bitrate (kbps)";
657 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
658 plot->title = "Incoming RTP bitrate";
659 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
660 plot->title = "Outgoing RTP bitrate";
661 }
662}
663
664// For each SSRC, plot the bandwidth used by that stream.
665void EventLogAnalyzer::CreateStreamBitrateGraph(
666 PacketDirection desired_direction,
667 Plot* plot) {
668 struct TimestampSize {
669 TimestampSize(uint64_t t, size_t s) : timestamp(t), size(s) {}
670 uint64_t timestamp;
671 size_t size;
672 };
terelius88e64e52016-07-19 01:51:06 -0700673 std::map<uint32_t, std::vector<TimestampSize>> packets;
terelius54ce6802016-07-13 06:44:41 -0700674
675 PacketDirection direction;
676 MediaType media_type;
677 uint8_t header[IP_PACKET_SIZE];
678 size_t header_length, total_length;
679
680 // Extract timestamps and sizes for the relevant packets.
681 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
682 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
683 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
684 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
685 &header_length, &total_length);
686 if (direction == desired_direction) {
687 // Parse header to get SSRC.
688 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
689 RTPHeader parsed_header;
690 rtp_parser.Parse(&parsed_header);
691 // Filter on SSRC.
692 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
693 uint64_t timestamp = parsed_log_.GetTimestamp(i);
694 packets[parsed_header.ssrc].push_back(
695 TimestampSize(timestamp, total_length));
696 }
697 }
698 }
699 }
700
701 float max_y = 0;
702
703 for (auto& kv : packets) {
704 size_t window_index_begin = 0;
705 size_t window_index_end = 0;
706 size_t bytes_in_window = 0;
707
708 // Calculate a moving average of the bitrate and store in a TimeSeries.
709 plot->series.push_back(TimeSeries());
710 for (uint64_t time = begin_time_; time < end_time_ + step_; time += step_) {
711 while (window_index_end < kv.second.size() &&
712 kv.second[window_index_end].timestamp < time) {
713 bytes_in_window += kv.second[window_index_end].size;
714 window_index_end++;
715 }
716 while (window_index_begin < kv.second.size() &&
717 kv.second[window_index_begin].timestamp <
718 time - window_duration_) {
719 RTC_DCHECK_LE(kv.second[window_index_begin].size, bytes_in_window);
720 bytes_in_window -= kv.second[window_index_begin].size;
721 window_index_begin++;
722 }
723 float window_duration_in_seconds =
724 static_cast<float>(window_duration_) / 1000000;
725 float x = static_cast<float>(time - begin_time_) / 1000000;
726 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
727 max_y = std::max(max_y, y);
728 plot->series.back().points.push_back(TimeSeriesPoint(x, y));
729 }
730
731 // Set labels.
732 plot->series.back().label = SsrcToString(kv.first);
733 plot->series.back().style = LINE_GRAPH;
734 }
735
736 plot->xaxis_min = kDefaultXMin;
737 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
738 plot->xaxis_label = "Time (s)";
739 plot->yaxis_min = kDefaultYMin;
740 plot->yaxis_max = max_y * kYMargin;
741 plot->yaxis_label = "Bitrate (kbps)";
742 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
743 plot->title = "Incoming bitrate per stream";
744 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
745 plot->title = "Outgoing bitrate per stream";
746 }
747}
748
Stefan Holmer13181032016-07-29 14:48:54 +0200749void EventLogAnalyzer::CreateBweGraph(Plot* plot) {
750 std::map<uint64_t, const LoggedRtpPacket*> outgoing_rtp;
751 std::map<uint64_t, const LoggedRtcpPacket*> incoming_rtcp;
752
753 for (const auto& kv : rtp_packets_) {
754 if (kv.first.GetDirection() == PacketDirection::kOutgoingPacket) {
755 for (const LoggedRtpPacket& rtp_packet : kv.second)
756 outgoing_rtp.insert(std::make_pair(rtp_packet.timestamp, &rtp_packet));
757 }
758 }
759
760 for (const auto& kv : rtcp_packets_) {
761 if (kv.first.GetDirection() == PacketDirection::kIncomingPacket) {
762 for (const LoggedRtcpPacket& rtcp_packet : kv.second)
763 incoming_rtcp.insert(
764 std::make_pair(rtcp_packet.timestamp, &rtcp_packet));
765 }
766 }
767
768 SimulatedClock clock(0);
769 BitrateObserver observer;
770 RtcEventLogNullImpl null_event_log;
771 CongestionController cc(&clock, &observer, &observer, &null_event_log);
772 // TODO(holmer): Log the call config and use that here instead.
773 static const uint32_t kDefaultStartBitrateBps = 300000;
774 cc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
775
776 TimeSeries time_series;
777 time_series.label = "BWE";
778 time_series.style = LINE_DOT_GRAPH;
779 uint32_t max_y = 10;
780 uint32_t min_y = 0;
781
782 auto rtp_iterator = outgoing_rtp.begin();
783 auto rtcp_iterator = incoming_rtcp.begin();
784
785 auto NextRtpTime = [&]() {
786 if (rtp_iterator != outgoing_rtp.end())
787 return static_cast<int64_t>(rtp_iterator->first);
788 return std::numeric_limits<int64_t>::max();
789 };
790
791 auto NextRtcpTime = [&]() {
792 if (rtcp_iterator != incoming_rtcp.end())
793 return static_cast<int64_t>(rtcp_iterator->first);
794 return std::numeric_limits<int64_t>::max();
795 };
796
797 auto NextProcessTime = [&]() {
798 if (rtcp_iterator != incoming_rtcp.end() ||
799 rtp_iterator != outgoing_rtp.end()) {
800 return clock.TimeInMicroseconds() +
801 std::max<int64_t>(cc.TimeUntilNextProcess() * 1000, 0);
802 }
803 return std::numeric_limits<int64_t>::max();
804 };
805
806 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
807 while (time_us != std::numeric_limits<int64_t>::max()) {
808 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
809 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
810 clock.AdvanceTimeMilliseconds(rtcp_iterator->first / 1000 -
811 clock.TimeInMilliseconds());
812 const LoggedRtcpPacket& rtcp = *rtcp_iterator->second;
813 if (rtcp.type == kRtcpTransportFeedback) {
814 cc.GetTransportFeedbackObserver()->OnTransportFeedback(
815 *static_cast<rtcp::TransportFeedback*>(rtcp.packet.get()));
816 }
817 ++rtcp_iterator;
818 }
819 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
820 clock.AdvanceTimeMilliseconds(rtp_iterator->first / 1000 -
821 clock.TimeInMilliseconds());
822 const LoggedRtpPacket& rtp = *rtp_iterator->second;
823 if (rtp.header.extension.hasTransportSequenceNumber) {
824 RTC_DCHECK(rtp.header.extension.hasTransportSequenceNumber);
825 cc.GetTransportFeedbackObserver()->AddPacket(
826 rtp.header.extension.transportSequenceNumber, rtp.total_length, 0);
827 rtc::SentPacket sent_packet(
828 rtp.header.extension.transportSequenceNumber, rtp.timestamp / 1000);
829 cc.OnSentPacket(sent_packet);
830 }
831 ++rtp_iterator;
832 }
833 if (clock.TimeInMicroseconds() >= NextProcessTime())
834 cc.Process();
835 if (observer.GetAndResetBitrateUpdated()) {
836 uint32_t y = observer.last_bitrate_bps() / 1000;
837 max_y = std::max(max_y, y);
838 min_y = std::min(min_y, y);
839 float x = static_cast<float>(clock.TimeInMicroseconds() - begin_time_) /
840 1000000;
841 time_series.points.emplace_back(x, y);
842 }
843 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
844 }
845 // Add the data set to the plot.
846 plot->series.push_back(std::move(time_series));
847
848 plot->xaxis_min = kDefaultXMin;
849 plot->xaxis_max = (end_time_ - begin_time_) / 1000000 * kXMargin;
850 plot->xaxis_label = "Time (s)";
851 plot->yaxis_min = min_y - (kYMargin - 1) / 2 * (max_y - min_y);
852 plot->yaxis_max = max_y + (kYMargin - 1) / 2 * (max_y - min_y);
853 plot->yaxis_label = "Bitrate (kbps)";
854 plot->title = "BWE";
855}
856
terelius54ce6802016-07-13 06:44:41 -0700857} // namespace plotting
858} // namespace webrtc