blob: c97a30fc0ebc8dc8ddee49372d3491f62ccdcb02 [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
tereliusdc35dcd2016-08-01 12:03:27 -070035namespace webrtc {
36namespace plotting {
37
terelius54ce6802016-07-13 06:44:41 -070038namespace {
39
40std::string SsrcToString(uint32_t ssrc) {
41 std::stringstream ss;
42 ss << "SSRC " << ssrc;
43 return ss.str();
44}
45
46// Checks whether an SSRC is contained in the list of desired SSRCs.
47// Note that an empty SSRC list matches every SSRC.
48bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
49 if (desired_ssrc.size() == 0)
50 return true;
51 return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
52 desired_ssrc.end();
53}
54
55double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
56 // The timestamp is a fixed point representation with 6 bits for seconds
57 // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
58 // time in seconds and then multiply by 1000000 to convert to microseconds.
59 static constexpr double kTimestampToMicroSec =
60 1000000.0 / static_cast<double>(1 << 18);
61 return abs_send_time * kTimestampToMicroSec;
62}
63
64// Computes the difference |later| - |earlier| where |later| and |earlier|
65// are counters that wrap at |modulus|. The difference is chosen to have the
66// least absolute value. For example if |modulus| is 8, then the difference will
67// be chosen in the range [-3, 4]. If |modulus| is 9, then the difference will
68// be in [-4, 4].
69int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
70 RTC_DCHECK_LE(1, modulus);
71 RTC_DCHECK_LT(later, modulus);
72 RTC_DCHECK_LT(earlier, modulus);
73 int64_t difference =
74 static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
75 int64_t max_difference = modulus / 2;
76 int64_t min_difference = max_difference - modulus + 1;
77 if (difference > max_difference) {
78 difference -= modulus;
79 }
80 if (difference < min_difference) {
81 difference += modulus;
82 }
83 return difference;
84}
85
stefan6a850c32016-07-29 10:28:08 -070086void RegisterHeaderExtensions(
87 const std::vector<webrtc::RtpExtension>& extensions,
88 webrtc::RtpHeaderExtensionMap* extension_map) {
89 extension_map->Erase();
90 for (const webrtc::RtpExtension& extension : extensions) {
91 extension_map->Register(webrtc::StringToRtpExtensionType(extension.uri),
92 extension.id);
93 }
94}
95
tereliusdc35dcd2016-08-01 12:03:27 -070096constexpr float kLeftMargin = 0.01f;
97constexpr float kRightMargin = 0.02f;
98constexpr float kBottomMargin = 0.02f;
99constexpr float kTopMargin = 0.05f;
terelius54ce6802016-07-13 06:44:41 -0700100
101} // namespace
102
terelius88e64e52016-07-19 01:51:06 -0700103bool EventLogAnalyzer::StreamId::operator<(const StreamId& other) const {
104 if (ssrc_ < other.ssrc_) {
105 return true;
106 }
107 if (ssrc_ == other.ssrc_) {
Stefan Holmer13181032016-07-29 14:48:54 +0200108 if (direction_ < other.direction_) {
terelius88e64e52016-07-19 01:51:06 -0700109 return true;
110 }
terelius88e64e52016-07-19 01:51:06 -0700111 }
112 return false;
113}
114
115bool EventLogAnalyzer::StreamId::operator==(const StreamId& other) const {
Stefan Holmer13181032016-07-29 14:48:54 +0200116 return ssrc_ == other.ssrc_ && direction_ == other.direction_;
terelius88e64e52016-07-19 01:51:06 -0700117}
118
119
terelius54ce6802016-07-13 06:44:41 -0700120EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log)
121 : parsed_log_(log), window_duration_(250000), step_(10000) {
122 uint64_t first_timestamp = std::numeric_limits<uint64_t>::max();
123 uint64_t last_timestamp = std::numeric_limits<uint64_t>::min();
terelius88e64e52016-07-19 01:51:06 -0700124
Stefan Holmer13181032016-07-29 14:48:54 +0200125 // Maps a stream identifier consisting of ssrc and direction
terelius88e64e52016-07-19 01:51:06 -0700126 // to the header extensions used by that stream,
127 std::map<StreamId, RtpHeaderExtensionMap> extension_maps;
128
129 PacketDirection direction;
terelius88e64e52016-07-19 01:51:06 -0700130 uint8_t header[IP_PACKET_SIZE];
131 size_t header_length;
132 size_t total_length;
133
terelius54ce6802016-07-13 06:44:41 -0700134 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
135 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
terelius88e64e52016-07-19 01:51:06 -0700136 if (event_type != ParsedRtcEventLog::VIDEO_RECEIVER_CONFIG_EVENT &&
137 event_type != ParsedRtcEventLog::VIDEO_SENDER_CONFIG_EVENT &&
138 event_type != ParsedRtcEventLog::AUDIO_RECEIVER_CONFIG_EVENT &&
terelius88c1d2b2016-08-01 05:20:33 -0700139 event_type != ParsedRtcEventLog::AUDIO_SENDER_CONFIG_EVENT &&
140 event_type != ParsedRtcEventLog::LOG_START &&
141 event_type != ParsedRtcEventLog::LOG_END) {
terelius88e64e52016-07-19 01:51:06 -0700142 uint64_t timestamp = parsed_log_.GetTimestamp(i);
143 first_timestamp = std::min(first_timestamp, timestamp);
144 last_timestamp = std::max(last_timestamp, timestamp);
145 }
146
147 switch (parsed_log_.GetEventType(i)) {
148 case ParsedRtcEventLog::VIDEO_RECEIVER_CONFIG_EVENT: {
149 VideoReceiveStream::Config config(nullptr);
150 parsed_log_.GetVideoReceiveConfig(i, &config);
Stefan Holmer13181032016-07-29 14:48:54 +0200151 StreamId stream(config.rtp.remote_ssrc, kIncomingPacket);
stefan6a850c32016-07-29 10:28:08 -0700152 RegisterHeaderExtensions(config.rtp.extensions,
153 &extension_maps[stream]);
154 for (auto kv : config.rtp.rtx) {
155 StreamId rtx_stream(kv.second.ssrc, kIncomingPacket);
156 RegisterHeaderExtensions(config.rtp.extensions,
157 &extension_maps[rtx_stream]);
terelius88e64e52016-07-19 01:51:06 -0700158 }
159 break;
160 }
161 case ParsedRtcEventLog::VIDEO_SENDER_CONFIG_EVENT: {
162 VideoSendStream::Config config(nullptr);
163 parsed_log_.GetVideoSendConfig(i, &config);
164 for (auto ssrc : config.rtp.ssrcs) {
Stefan Holmer13181032016-07-29 14:48:54 +0200165 StreamId stream(ssrc, kOutgoingPacket);
stefan6a850c32016-07-29 10:28:08 -0700166 RegisterHeaderExtensions(config.rtp.extensions,
167 &extension_maps[stream]);
168 }
169 for (auto ssrc : config.rtp.rtx.ssrcs) {
170 StreamId stream(ssrc, kOutgoingPacket);
171 RegisterHeaderExtensions(config.rtp.extensions,
172 &extension_maps[stream]);
terelius88e64e52016-07-19 01:51:06 -0700173 }
174 break;
175 }
176 case ParsedRtcEventLog::AUDIO_RECEIVER_CONFIG_EVENT: {
177 AudioReceiveStream::Config config;
178 // TODO(terelius): Parse the audio configs once we have them.
179 break;
180 }
181 case ParsedRtcEventLog::AUDIO_SENDER_CONFIG_EVENT: {
182 AudioSendStream::Config config(nullptr);
183 // TODO(terelius): Parse the audio configs once we have them.
184 break;
185 }
186 case ParsedRtcEventLog::RTP_EVENT: {
Stefan Holmer13181032016-07-29 14:48:54 +0200187 MediaType media_type;
terelius88e64e52016-07-19 01:51:06 -0700188 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
189 &header_length, &total_length);
190 // Parse header to get SSRC.
191 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
192 RTPHeader parsed_header;
193 rtp_parser.Parse(&parsed_header);
Stefan Holmer13181032016-07-29 14:48:54 +0200194 StreamId stream(parsed_header.ssrc, direction);
terelius88e64e52016-07-19 01:51:06 -0700195 // Look up the extension_map and parse it again to get the extensions.
196 if (extension_maps.count(stream) == 1) {
197 RtpHeaderExtensionMap* extension_map = &extension_maps[stream];
198 rtp_parser.Parse(&parsed_header, extension_map);
199 }
200 uint64_t timestamp = parsed_log_.GetTimestamp(i);
201 rtp_packets_[stream].push_back(
Stefan Holmer13181032016-07-29 14:48:54 +0200202 LoggedRtpPacket(timestamp, parsed_header, total_length));
terelius88e64e52016-07-19 01:51:06 -0700203 break;
204 }
205 case ParsedRtcEventLog::RTCP_EVENT: {
Stefan Holmer13181032016-07-29 14:48:54 +0200206 uint8_t packet[IP_PACKET_SIZE];
207 MediaType media_type;
208 parsed_log_.GetRtcpPacket(i, &direction, &media_type, packet,
209 &total_length);
210
211 RtpUtility::RtpHeaderParser rtp_parser(packet, total_length);
212 RTPHeader parsed_header;
213 RTC_CHECK(rtp_parser.ParseRtcp(&parsed_header));
214 uint32_t ssrc = parsed_header.ssrc;
215
216 RTCPUtility::RTCPParserV2 rtcp_parser(packet, total_length, true);
217 RTC_CHECK(rtcp_parser.IsValid());
218
219 RTCPUtility::RTCPPacketTypes packet_type = rtcp_parser.Begin();
220 while (packet_type != RTCPUtility::RTCPPacketTypes::kInvalid) {
221 switch (packet_type) {
222 case RTCPUtility::RTCPPacketTypes::kTransportFeedback: {
223 // Currently feedback is logged twice, both for audio and video.
224 // Only act on one of them.
225 if (media_type == MediaType::VIDEO) {
226 std::unique_ptr<rtcp::RtcpPacket> rtcp_packet(
227 rtcp_parser.ReleaseRtcpPacket());
228 StreamId stream(ssrc, direction);
229 uint64_t timestamp = parsed_log_.GetTimestamp(i);
230 rtcp_packets_[stream].push_back(LoggedRtcpPacket(
231 timestamp, kRtcpTransportFeedback, std::move(rtcp_packet)));
232 }
233 break;
234 }
235 default:
236 break;
237 }
238 rtcp_parser.Iterate();
239 packet_type = rtcp_parser.PacketType();
240 }
terelius88e64e52016-07-19 01:51:06 -0700241 break;
242 }
243 case ParsedRtcEventLog::LOG_START: {
244 break;
245 }
246 case ParsedRtcEventLog::LOG_END: {
247 break;
248 }
249 case ParsedRtcEventLog::BWE_PACKET_LOSS_EVENT: {
terelius8058e582016-07-25 01:32:41 -0700250 BwePacketLossEvent bwe_update;
251 bwe_update.timestamp = parsed_log_.GetTimestamp(i);
252 parsed_log_.GetBwePacketLossEvent(i, &bwe_update.new_bitrate,
253 &bwe_update.fraction_loss,
254 &bwe_update.expected_packets);
255 bwe_loss_updates_.push_back(bwe_update);
terelius88e64e52016-07-19 01:51:06 -0700256 break;
257 }
258 case ParsedRtcEventLog::BWE_PACKET_DELAY_EVENT: {
259 break;
260 }
261 case ParsedRtcEventLog::AUDIO_PLAYOUT_EVENT: {
262 break;
263 }
264 case ParsedRtcEventLog::UNKNOWN_EVENT: {
265 break;
266 }
267 }
terelius54ce6802016-07-13 06:44:41 -0700268 }
terelius88e64e52016-07-19 01:51:06 -0700269
terelius54ce6802016-07-13 06:44:41 -0700270 if (last_timestamp < first_timestamp) {
271 // No useful events in the log.
272 first_timestamp = last_timestamp = 0;
273 }
274 begin_time_ = first_timestamp;
275 end_time_ = last_timestamp;
tereliusdc35dcd2016-08-01 12:03:27 -0700276 call_duration_s_ = static_cast<float>(end_time_ - begin_time_) / 1000000;
terelius54ce6802016-07-13 06:44:41 -0700277}
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;
terelius54ce6802016-07-13 06:44:41 -0700314
315 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
316 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
317 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
318 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
319 &header_length, &total_length);
320 if (direction == desired_direction) {
321 // Parse header to get SSRC.
322 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
323 RTPHeader parsed_header;
324 rtp_parser.Parse(&parsed_header);
325 // Filter on SSRC.
326 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
327 uint64_t timestamp = parsed_log_.GetTimestamp(i);
328 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
329 float y = total_length;
terelius54ce6802016-07-13 06:44:41 -0700330 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;
tereliusdc35dcd2016-08-01 12:03:27 -0700341 plot->series_list_.push_back(std::move(kv.second));
terelius54ce6802016-07-13 06:44:41 -0700342 }
343
tereliusdc35dcd2016-08-01 12:03:27 -0700344 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
345 plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
346 kTopMargin);
terelius54ce6802016-07-13 06:44:41 -0700347 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700348 plot->SetTitle("Incoming RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700349 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700350 plot->SetTitle("Outgoing RTP packets");
terelius54ce6802016-07-13 06:44:41 -0700351 }
352}
353
354// For each SSRC, plot the time between the consecutive playouts.
355void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
356 std::map<uint32_t, TimeSeries> time_series;
357 std::map<uint32_t, uint64_t> last_playout;
358
359 uint32_t ssrc;
terelius54ce6802016-07-13 06:44:41 -0700360
361 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
362 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
363 if (event_type == ParsedRtcEventLog::AUDIO_PLAYOUT_EVENT) {
364 parsed_log_.GetAudioPlayout(i, &ssrc);
365 uint64_t timestamp = parsed_log_.GetTimestamp(i);
366 if (MatchingSsrc(ssrc, desired_ssrc_)) {
367 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
368 float y = static_cast<float>(timestamp - last_playout[ssrc]) / 1000;
369 if (time_series[ssrc].points.size() == 0) {
370 // There were no previusly logged playout for this SSRC.
371 // Generate a point, but place it on the x-axis.
372 y = 0;
373 }
terelius54ce6802016-07-13 06:44:41 -0700374 time_series[ssrc].points.push_back(TimeSeriesPoint(x, y));
375 last_playout[ssrc] = timestamp;
376 }
377 }
378 }
379
380 // Set labels and put in graph.
381 for (auto& kv : time_series) {
382 kv.second.label = SsrcToString(kv.first);
383 kv.second.style = BAR_GRAPH;
tereliusdc35dcd2016-08-01 12:03:27 -0700384 plot->series_list_.push_back(std::move(kv.second));
terelius54ce6802016-07-13 06:44:41 -0700385 }
386
tereliusdc35dcd2016-08-01 12:03:27 -0700387 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
388 plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
389 kTopMargin);
390 plot->SetTitle("Audio playout");
terelius54ce6802016-07-13 06:44:41 -0700391}
392
393// For each SSRC, plot the time between the consecutive playouts.
394void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
395 std::map<uint32_t, TimeSeries> time_series;
396 std::map<uint32_t, uint16_t> last_seqno;
397
398 PacketDirection direction;
399 MediaType media_type;
400 uint8_t header[IP_PACKET_SIZE];
401 size_t header_length, total_length;
402
terelius54ce6802016-07-13 06:44:41 -0700403 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
404 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
405 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
406 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
407 &header_length, &total_length);
408 uint64_t timestamp = parsed_log_.GetTimestamp(i);
409 if (direction == PacketDirection::kIncomingPacket) {
410 // Parse header to get SSRC.
411 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
412 RTPHeader parsed_header;
413 rtp_parser.Parse(&parsed_header);
414 // Filter on SSRC.
415 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
416 float x = static_cast<float>(timestamp - begin_time_) / 1000000;
417 int y = WrappingDifference(parsed_header.sequenceNumber,
418 last_seqno[parsed_header.ssrc], 1ul << 16);
419 if (time_series[parsed_header.ssrc].points.size() == 0) {
420 // There were no previusly logged playout for this SSRC.
421 // Generate a point, but place it on the x-axis.
422 y = 0;
423 }
terelius54ce6802016-07-13 06:44:41 -0700424 time_series[parsed_header.ssrc].points.push_back(
425 TimeSeriesPoint(x, y));
426 last_seqno[parsed_header.ssrc] = parsed_header.sequenceNumber;
427 }
428 }
429 }
430 }
431
432 // Set labels and put in graph.
433 for (auto& kv : time_series) {
434 kv.second.label = SsrcToString(kv.first);
435 kv.second.style = BAR_GRAPH;
tereliusdc35dcd2016-08-01 12:03:27 -0700436 plot->series_list_.push_back(std::move(kv.second));
terelius54ce6802016-07-13 06:44:41 -0700437 }
438
tereliusdc35dcd2016-08-01 12:03:27 -0700439 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
440 plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
441 kTopMargin);
442 plot->SetTitle("Sequence number");
terelius54ce6802016-07-13 06:44:41 -0700443}
444
445void EventLogAnalyzer::CreateDelayChangeGraph(Plot* plot) {
terelius88e64e52016-07-19 01:51:06 -0700446 for (auto& kv : rtp_packets_) {
447 StreamId stream_id = kv.first;
448 // Filter on direction and SSRC.
449 if (stream_id.GetDirection() != kIncomingPacket ||
450 !MatchingSsrc(stream_id.GetSsrc(), desired_ssrc_)) {
451 continue;
452 }
terelius54ce6802016-07-13 06:44:41 -0700453
terelius88e64e52016-07-19 01:51:06 -0700454 TimeSeries time_series;
455 time_series.label = SsrcToString(stream_id.GetSsrc());
456 time_series.style = BAR_GRAPH;
457 const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
458 int64_t last_abs_send_time = 0;
459 int64_t last_timestamp = 0;
460 for (const LoggedRtpPacket& packet : packet_stream) {
461 if (packet.header.extension.hasAbsoluteSendTime) {
462 int64_t send_time_diff =
463 WrappingDifference(packet.header.extension.absoluteSendTime,
464 last_abs_send_time, 1ul << 24);
465 int64_t recv_time_diff = packet.timestamp - last_timestamp;
466
467 last_abs_send_time = packet.header.extension.absoluteSendTime;
468 last_timestamp = packet.timestamp;
469
470 float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
471 double y =
472 static_cast<double>(recv_time_diff -
473 AbsSendTimeToMicroseconds(send_time_diff)) /
474 1000;
475 if (time_series.points.size() == 0) {
476 // There were no previously logged packets for this SSRC.
477 // Generate a point, but place it on the x-axis.
478 y = 0;
terelius54ce6802016-07-13 06:44:41 -0700479 }
terelius88e64e52016-07-19 01:51:06 -0700480 time_series.points.emplace_back(x, y);
terelius54ce6802016-07-13 06:44:41 -0700481 }
482 }
terelius88e64e52016-07-19 01:51:06 -0700483 // Add the data set to the plot.
tereliusdc35dcd2016-08-01 12:03:27 -0700484 plot->series_list_.push_back(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700485 }
486
tereliusdc35dcd2016-08-01 12:03:27 -0700487 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
488 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
489 kTopMargin);
490 plot->SetTitle("Network latency change between consecutive packets");
terelius54ce6802016-07-13 06:44:41 -0700491}
492
493void EventLogAnalyzer::CreateAccumulatedDelayChangeGraph(Plot* plot) {
terelius88e64e52016-07-19 01:51:06 -0700494 for (auto& kv : rtp_packets_) {
495 StreamId stream_id = kv.first;
496 // Filter on direction and SSRC.
497 if (stream_id.GetDirection() != kIncomingPacket ||
498 !MatchingSsrc(stream_id.GetSsrc(), desired_ssrc_)) {
499 continue;
500 }
501 TimeSeries time_series;
502 time_series.label = SsrcToString(stream_id.GetSsrc());
503 time_series.style = LINE_GRAPH;
504 const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
505 int64_t last_abs_send_time = 0;
506 int64_t last_timestamp = 0;
507 double accumulated_delay_ms = 0;
508 for (const LoggedRtpPacket& packet : packet_stream) {
509 if (packet.header.extension.hasAbsoluteSendTime) {
510 int64_t send_time_diff =
511 WrappingDifference(packet.header.extension.absoluteSendTime,
512 last_abs_send_time, 1ul << 24);
513 int64_t recv_time_diff = packet.timestamp - last_timestamp;
terelius54ce6802016-07-13 06:44:41 -0700514
terelius88e64e52016-07-19 01:51:06 -0700515 last_abs_send_time = packet.header.extension.absoluteSendTime;
516 last_timestamp = packet.timestamp;
517
518 float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
519 accumulated_delay_ms +=
520 static_cast<double>(recv_time_diff -
521 AbsSendTimeToMicroseconds(send_time_diff)) /
522 1000;
523 if (time_series.points.size() == 0) {
524 // There were no previously logged packets for this SSRC.
525 // Generate a point, but place it on the x-axis.
526 accumulated_delay_ms = 0;
terelius54ce6802016-07-13 06:44:41 -0700527 }
terelius88e64e52016-07-19 01:51:06 -0700528 time_series.points.emplace_back(x, accumulated_delay_ms);
terelius54ce6802016-07-13 06:44:41 -0700529 }
530 }
terelius88e64e52016-07-19 01:51:06 -0700531 // Add the data set to the plot.
tereliusdc35dcd2016-08-01 12:03:27 -0700532 plot->series_list_.push_back(std::move(time_series));
terelius54ce6802016-07-13 06:44:41 -0700533 }
534
tereliusdc35dcd2016-08-01 12:03:27 -0700535 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
536 plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
537 kTopMargin);
538 plot->SetTitle("Accumulated network latency change");
terelius54ce6802016-07-13 06:44:41 -0700539}
540
541// Plot the total bandwidth used by all RTP streams.
542void EventLogAnalyzer::CreateTotalBitrateGraph(
543 PacketDirection desired_direction,
544 Plot* plot) {
545 struct TimestampSize {
546 TimestampSize(uint64_t t, size_t s) : timestamp(t), size(s) {}
547 uint64_t timestamp;
548 size_t size;
549 };
550 std::vector<TimestampSize> packets;
551
552 PacketDirection direction;
553 size_t total_length;
554
555 // Extract timestamps and sizes for the relevant packets.
556 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
557 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
558 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
559 parsed_log_.GetRtpHeader(i, &direction, nullptr, nullptr, nullptr,
560 &total_length);
561 if (direction == desired_direction) {
562 uint64_t timestamp = parsed_log_.GetTimestamp(i);
563 packets.push_back(TimestampSize(timestamp, total_length));
564 }
565 }
566 }
567
568 size_t window_index_begin = 0;
569 size_t window_index_end = 0;
570 size_t bytes_in_window = 0;
terelius54ce6802016-07-13 06:44:41 -0700571
572 // Calculate a moving average of the bitrate and store in a TimeSeries.
tereliusdc35dcd2016-08-01 12:03:27 -0700573 plot->series_list_.push_back(TimeSeries());
terelius54ce6802016-07-13 06:44:41 -0700574 for (uint64_t time = begin_time_; time < end_time_ + step_; time += step_) {
575 while (window_index_end < packets.size() &&
576 packets[window_index_end].timestamp < time) {
577 bytes_in_window += packets[window_index_end].size;
578 window_index_end++;
579 }
580 while (window_index_begin < packets.size() &&
581 packets[window_index_begin].timestamp < time - window_duration_) {
582 RTC_DCHECK_LE(packets[window_index_begin].size, bytes_in_window);
583 bytes_in_window -= packets[window_index_begin].size;
584 window_index_begin++;
585 }
586 float window_duration_in_seconds =
587 static_cast<float>(window_duration_) / 1000000;
588 float x = static_cast<float>(time - begin_time_) / 1000000;
589 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
tereliusdc35dcd2016-08-01 12:03:27 -0700590 plot->series_list_.back().points.push_back(TimeSeriesPoint(x, y));
terelius54ce6802016-07-13 06:44:41 -0700591 }
592
593 // Set labels.
594 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700595 plot->series_list_.back().label = "Incoming bitrate";
terelius54ce6802016-07-13 06:44:41 -0700596 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700597 plot->series_list_.back().label = "Outgoing bitrate";
terelius54ce6802016-07-13 06:44:41 -0700598 }
tereliusdc35dcd2016-08-01 12:03:27 -0700599 plot->series_list_.back().style = LINE_GRAPH;
terelius54ce6802016-07-13 06:44:41 -0700600
terelius8058e582016-07-25 01:32:41 -0700601 // Overlay the send-side bandwidth estimate over the outgoing bitrate.
602 if (desired_direction == kOutgoingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700603 plot->series_list_.push_back(TimeSeries());
terelius8058e582016-07-25 01:32:41 -0700604 for (auto& bwe_update : bwe_loss_updates_) {
605 float x =
606 static_cast<float>(bwe_update.timestamp - begin_time_) / 1000000;
607 float y = static_cast<float>(bwe_update.new_bitrate) / 1000;
tereliusdc35dcd2016-08-01 12:03:27 -0700608 plot->series_list_.back().points.emplace_back(x, y);
terelius8058e582016-07-25 01:32:41 -0700609 }
tereliusdc35dcd2016-08-01 12:03:27 -0700610 plot->series_list_.back().label = "Loss-based estimate";
611 plot->series_list_.back().style = LINE_GRAPH;
terelius8058e582016-07-25 01:32:41 -0700612 }
tereliusdc35dcd2016-08-01 12:03:27 -0700613 plot->series_list_.back().style = LINE_GRAPH;
614 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
615 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
terelius54ce6802016-07-13 06:44:41 -0700616 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700617 plot->SetTitle("Incoming RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -0700618 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700619 plot->SetTitle("Outgoing RTP bitrate");
terelius54ce6802016-07-13 06:44:41 -0700620 }
621}
622
623// For each SSRC, plot the bandwidth used by that stream.
624void EventLogAnalyzer::CreateStreamBitrateGraph(
625 PacketDirection desired_direction,
626 Plot* plot) {
627 struct TimestampSize {
628 TimestampSize(uint64_t t, size_t s) : timestamp(t), size(s) {}
629 uint64_t timestamp;
630 size_t size;
631 };
terelius88e64e52016-07-19 01:51:06 -0700632 std::map<uint32_t, std::vector<TimestampSize>> packets;
terelius54ce6802016-07-13 06:44:41 -0700633
634 PacketDirection direction;
635 MediaType media_type;
636 uint8_t header[IP_PACKET_SIZE];
637 size_t header_length, total_length;
638
639 // Extract timestamps and sizes for the relevant packets.
640 for (size_t i = 0; i < parsed_log_.GetNumberOfEvents(); i++) {
641 ParsedRtcEventLog::EventType event_type = parsed_log_.GetEventType(i);
642 if (event_type == ParsedRtcEventLog::RTP_EVENT) {
643 parsed_log_.GetRtpHeader(i, &direction, &media_type, header,
644 &header_length, &total_length);
645 if (direction == desired_direction) {
646 // Parse header to get SSRC.
647 RtpUtility::RtpHeaderParser rtp_parser(header, header_length);
648 RTPHeader parsed_header;
649 rtp_parser.Parse(&parsed_header);
650 // Filter on SSRC.
651 if (MatchingSsrc(parsed_header.ssrc, desired_ssrc_)) {
652 uint64_t timestamp = parsed_log_.GetTimestamp(i);
653 packets[parsed_header.ssrc].push_back(
654 TimestampSize(timestamp, total_length));
655 }
656 }
657 }
658 }
659
terelius54ce6802016-07-13 06:44:41 -0700660 for (auto& kv : packets) {
661 size_t window_index_begin = 0;
662 size_t window_index_end = 0;
663 size_t bytes_in_window = 0;
664
665 // Calculate a moving average of the bitrate and store in a TimeSeries.
tereliusdc35dcd2016-08-01 12:03:27 -0700666 plot->series_list_.push_back(TimeSeries());
terelius54ce6802016-07-13 06:44:41 -0700667 for (uint64_t time = begin_time_; time < end_time_ + step_; time += step_) {
668 while (window_index_end < kv.second.size() &&
669 kv.second[window_index_end].timestamp < time) {
670 bytes_in_window += kv.second[window_index_end].size;
671 window_index_end++;
672 }
673 while (window_index_begin < kv.second.size() &&
674 kv.second[window_index_begin].timestamp <
675 time - window_duration_) {
676 RTC_DCHECK_LE(kv.second[window_index_begin].size, bytes_in_window);
677 bytes_in_window -= kv.second[window_index_begin].size;
678 window_index_begin++;
679 }
680 float window_duration_in_seconds =
681 static_cast<float>(window_duration_) / 1000000;
682 float x = static_cast<float>(time - begin_time_) / 1000000;
683 float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
tereliusdc35dcd2016-08-01 12:03:27 -0700684 plot->series_list_.back().points.push_back(TimeSeriesPoint(x, y));
terelius54ce6802016-07-13 06:44:41 -0700685 }
686
687 // Set labels.
tereliusdc35dcd2016-08-01 12:03:27 -0700688 plot->series_list_.back().label = SsrcToString(kv.first);
689 plot->series_list_.back().style = LINE_GRAPH;
terelius54ce6802016-07-13 06:44:41 -0700690 }
691
tereliusdc35dcd2016-08-01 12:03:27 -0700692 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
693 plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
terelius54ce6802016-07-13 06:44:41 -0700694 if (desired_direction == webrtc::PacketDirection::kIncomingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700695 plot->SetTitle("Incoming bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -0700696 } else if (desired_direction == webrtc::PacketDirection::kOutgoingPacket) {
tereliusdc35dcd2016-08-01 12:03:27 -0700697 plot->SetTitle("Outgoing bitrate per stream");
terelius54ce6802016-07-13 06:44:41 -0700698 }
699}
700
Stefan Holmer13181032016-07-29 14:48:54 +0200701void EventLogAnalyzer::CreateBweGraph(Plot* plot) {
702 std::map<uint64_t, const LoggedRtpPacket*> outgoing_rtp;
703 std::map<uint64_t, const LoggedRtcpPacket*> incoming_rtcp;
704
705 for (const auto& kv : rtp_packets_) {
706 if (kv.first.GetDirection() == PacketDirection::kOutgoingPacket) {
707 for (const LoggedRtpPacket& rtp_packet : kv.second)
708 outgoing_rtp.insert(std::make_pair(rtp_packet.timestamp, &rtp_packet));
709 }
710 }
711
712 for (const auto& kv : rtcp_packets_) {
713 if (kv.first.GetDirection() == PacketDirection::kIncomingPacket) {
714 for (const LoggedRtcpPacket& rtcp_packet : kv.second)
715 incoming_rtcp.insert(
716 std::make_pair(rtcp_packet.timestamp, &rtcp_packet));
717 }
718 }
719
720 SimulatedClock clock(0);
721 BitrateObserver observer;
722 RtcEventLogNullImpl null_event_log;
723 CongestionController cc(&clock, &observer, &observer, &null_event_log);
724 // TODO(holmer): Log the call config and use that here instead.
725 static const uint32_t kDefaultStartBitrateBps = 300000;
726 cc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
727
728 TimeSeries time_series;
729 time_series.label = "BWE";
730 time_series.style = LINE_DOT_GRAPH;
Stefan Holmer13181032016-07-29 14:48:54 +0200731
732 auto rtp_iterator = outgoing_rtp.begin();
733 auto rtcp_iterator = incoming_rtcp.begin();
734
735 auto NextRtpTime = [&]() {
736 if (rtp_iterator != outgoing_rtp.end())
737 return static_cast<int64_t>(rtp_iterator->first);
738 return std::numeric_limits<int64_t>::max();
739 };
740
741 auto NextRtcpTime = [&]() {
742 if (rtcp_iterator != incoming_rtcp.end())
743 return static_cast<int64_t>(rtcp_iterator->first);
744 return std::numeric_limits<int64_t>::max();
745 };
746
747 auto NextProcessTime = [&]() {
748 if (rtcp_iterator != incoming_rtcp.end() ||
749 rtp_iterator != outgoing_rtp.end()) {
750 return clock.TimeInMicroseconds() +
751 std::max<int64_t>(cc.TimeUntilNextProcess() * 1000, 0);
752 }
753 return std::numeric_limits<int64_t>::max();
754 };
755
756 int64_t time_us = std::min(NextRtpTime(), NextRtcpTime());
757 while (time_us != std::numeric_limits<int64_t>::max()) {
758 clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
759 if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
760 clock.AdvanceTimeMilliseconds(rtcp_iterator->first / 1000 -
761 clock.TimeInMilliseconds());
762 const LoggedRtcpPacket& rtcp = *rtcp_iterator->second;
763 if (rtcp.type == kRtcpTransportFeedback) {
764 cc.GetTransportFeedbackObserver()->OnTransportFeedback(
765 *static_cast<rtcp::TransportFeedback*>(rtcp.packet.get()));
766 }
767 ++rtcp_iterator;
768 }
769 if (clock.TimeInMicroseconds() >= NextRtpTime()) {
770 clock.AdvanceTimeMilliseconds(rtp_iterator->first / 1000 -
771 clock.TimeInMilliseconds());
772 const LoggedRtpPacket& rtp = *rtp_iterator->second;
773 if (rtp.header.extension.hasTransportSequenceNumber) {
774 RTC_DCHECK(rtp.header.extension.hasTransportSequenceNumber);
775 cc.GetTransportFeedbackObserver()->AddPacket(
776 rtp.header.extension.transportSequenceNumber, rtp.total_length, 0);
777 rtc::SentPacket sent_packet(
778 rtp.header.extension.transportSequenceNumber, rtp.timestamp / 1000);
779 cc.OnSentPacket(sent_packet);
780 }
781 ++rtp_iterator;
782 }
783 if (clock.TimeInMicroseconds() >= NextProcessTime())
784 cc.Process();
785 if (observer.GetAndResetBitrateUpdated()) {
786 uint32_t y = observer.last_bitrate_bps() / 1000;
Stefan Holmer13181032016-07-29 14:48:54 +0200787 float x = static_cast<float>(clock.TimeInMicroseconds() - begin_time_) /
788 1000000;
789 time_series.points.emplace_back(x, y);
790 }
791 time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
792 }
793 // Add the data set to the plot.
tereliusdc35dcd2016-08-01 12:03:27 -0700794 plot->series_list_.push_back(std::move(time_series));
Stefan Holmer13181032016-07-29 14:48:54 +0200795
tereliusdc35dcd2016-08-01 12:03:27 -0700796 plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
797 plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
798 plot->SetTitle("Simulated BWE behavior");
Stefan Holmer13181032016-07-29 14:48:54 +0200799}
800
terelius54ce6802016-07-13 06:44:41 -0700801} // namespace plotting
802} // namespace webrtc