xref: /aosp_15_r20/external/webrtc/rtc_tools/rtc_event_log_visualizer/analyzer.cc (revision d9f758449e529ab9291ac668be2861e7a55c2422)
1 /*
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 "rtc_tools/rtc_event_log_visualizer/analyzer.h"
12 
13 #include <algorithm>
14 #include <cmath>
15 #include <limits>
16 #include <map>
17 #include <memory>
18 #include <string>
19 #include <utility>
20 
21 #include "absl/algorithm/container.h"
22 #include "absl/functional/bind_front.h"
23 #include "absl/strings/string_view.h"
24 #include "api/function_view.h"
25 #include "api/network_state_predictor.h"
26 #include "api/transport/field_trial_based_config.h"
27 #include "api/transport/goog_cc_factory.h"
28 #include "call/audio_receive_stream.h"
29 #include "call/audio_send_stream.h"
30 #include "call/call.h"
31 #include "call/video_receive_stream.h"
32 #include "call/video_send_stream.h"
33 #include "logging/rtc_event_log/rtc_event_processor.h"
34 #include "logging/rtc_event_log/rtc_stream_config.h"
35 #include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h"
36 #include "modules/congestion_controller/goog_cc/acknowledged_bitrate_estimator.h"
37 #include "modules/congestion_controller/goog_cc/bitrate_estimator.h"
38 #include "modules/congestion_controller/goog_cc/delay_based_bwe.h"
39 #include "modules/congestion_controller/include/receive_side_congestion_controller.h"
40 #include "modules/congestion_controller/rtp/transport_feedback_adapter.h"
41 #include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
42 #include "modules/rtp_rtcp/source/rtcp_packet.h"
43 #include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
44 #include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
45 #include "modules/rtp_rtcp/source/rtcp_packet/remb.h"
46 #include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
47 #include "modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
48 #include "modules/rtp_rtcp/source/rtp_header_extensions.h"
49 #include "modules/rtp_rtcp/source/rtp_rtcp_interface.h"
50 #include "rtc_base/checks.h"
51 #include "rtc_base/logging.h"
52 #include "rtc_base/numerics/sequence_number_util.h"
53 #include "rtc_base/rate_statistics.h"
54 #include "rtc_base/strings/string_builder.h"
55 #include "rtc_tools/rtc_event_log_visualizer/log_simulation.h"
56 #include "test/explicit_key_value_config.h"
57 
58 namespace webrtc {
59 
60 namespace {
61 
SsrcToString(uint32_t ssrc)62 std::string SsrcToString(uint32_t ssrc) {
63   rtc::StringBuilder ss;
64   ss << "SSRC " << ssrc;
65   return ss.Release();
66 }
67 
68 // Checks whether an SSRC is contained in the list of desired SSRCs.
69 // Note that an empty SSRC list matches every SSRC.
MatchingSsrc(uint32_t ssrc,const std::vector<uint32_t> & desired_ssrc)70 bool MatchingSsrc(uint32_t ssrc, const std::vector<uint32_t>& desired_ssrc) {
71   if (desired_ssrc.empty())
72     return true;
73   return std::find(desired_ssrc.begin(), desired_ssrc.end(), ssrc) !=
74          desired_ssrc.end();
75 }
76 
AbsSendTimeToMicroseconds(int64_t abs_send_time)77 double AbsSendTimeToMicroseconds(int64_t abs_send_time) {
78   // The timestamp is a fixed point representation with 6 bits for seconds
79   // and 18 bits for fractions of a second. Thus, we divide by 2^18 to get the
80   // time in seconds and then multiply by kNumMicrosecsPerSec to convert to
81   // microseconds.
82   static constexpr double kTimestampToMicroSec =
83       static_cast<double>(kNumMicrosecsPerSec) / static_cast<double>(1ul << 18);
84   return abs_send_time * kTimestampToMicroSec;
85 }
86 
87 // Computes the difference `later` - `earlier` where `later` and `earlier`
88 // are counters that wrap at `modulus`. The difference is chosen to have the
89 // least absolute value. For example if `modulus` is 8, then the difference will
90 // be chosen in the range [-3, 4]. If `modulus` is 9, then the difference will
91 // be in [-4, 4].
WrappingDifference(uint32_t later,uint32_t earlier,int64_t modulus)92 int64_t WrappingDifference(uint32_t later, uint32_t earlier, int64_t modulus) {
93   RTC_DCHECK_LE(1, modulus);
94   RTC_DCHECK_LT(later, modulus);
95   RTC_DCHECK_LT(earlier, modulus);
96   int64_t difference =
97       static_cast<int64_t>(later) - static_cast<int64_t>(earlier);
98   int64_t max_difference = modulus / 2;
99   int64_t min_difference = max_difference - modulus + 1;
100   if (difference > max_difference) {
101     difference -= modulus;
102   }
103   if (difference < min_difference) {
104     difference += modulus;
105   }
106   if (difference > max_difference / 2 || difference < min_difference / 2) {
107     RTC_LOG(LS_WARNING) << "Difference between" << later << " and " << earlier
108                         << " expected to be in the range ("
109                         << min_difference / 2 << "," << max_difference / 2
110                         << ") but is " << difference
111                         << ". Correct unwrapping is uncertain.";
112   }
113   return difference;
114 }
115 
116 // This is much more reliable for outgoing streams than for incoming streams.
117 template <typename RtpPacketContainer>
EstimateRtpClockFrequency(const RtpPacketContainer & packets,int64_t end_time_us)118 absl::optional<uint32_t> EstimateRtpClockFrequency(
119     const RtpPacketContainer& packets,
120     int64_t end_time_us) {
121   RTC_CHECK(packets.size() >= 2);
122   SeqNumUnwrapper<uint32_t> unwrapper;
123   int64_t first_rtp_timestamp =
124       unwrapper.Unwrap(packets[0].rtp.header.timestamp);
125   int64_t first_log_timestamp = packets[0].log_time_us();
126   int64_t last_rtp_timestamp = first_rtp_timestamp;
127   int64_t last_log_timestamp = first_log_timestamp;
128   for (size_t i = 1; i < packets.size(); i++) {
129     if (packets[i].log_time_us() > end_time_us)
130       break;
131     last_rtp_timestamp = unwrapper.Unwrap(packets[i].rtp.header.timestamp);
132     last_log_timestamp = packets[i].log_time_us();
133   }
134   if (last_log_timestamp - first_log_timestamp < kNumMicrosecsPerSec) {
135     RTC_LOG(LS_WARNING)
136         << "Failed to estimate RTP clock frequency: Stream too short. ("
137         << packets.size() << " packets, "
138         << last_log_timestamp - first_log_timestamp << " us)";
139     return absl::nullopt;
140   }
141   double duration =
142       static_cast<double>(last_log_timestamp - first_log_timestamp) /
143       kNumMicrosecsPerSec;
144   double estimated_frequency =
145       (last_rtp_timestamp - first_rtp_timestamp) / duration;
146   for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) {
147     if (std::fabs(estimated_frequency - f) < 0.15 * f) {
148       return f;
149     }
150   }
151   RTC_LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
152                       << estimated_frequency
153                       << " not close to any standard RTP frequency."
154                       << " Last timestamp " << last_rtp_timestamp
155                       << " first timestamp " << first_rtp_timestamp;
156   return absl::nullopt;
157 }
158 
NetworkDelayDiff_AbsSendTime(const LoggedRtpPacketIncoming & old_packet,const LoggedRtpPacketIncoming & new_packet)159 absl::optional<double> NetworkDelayDiff_AbsSendTime(
160     const LoggedRtpPacketIncoming& old_packet,
161     const LoggedRtpPacketIncoming& new_packet) {
162   if (old_packet.rtp.header.extension.hasAbsoluteSendTime &&
163       new_packet.rtp.header.extension.hasAbsoluteSendTime) {
164     int64_t send_time_diff = WrappingDifference(
165         new_packet.rtp.header.extension.absoluteSendTime,
166         old_packet.rtp.header.extension.absoluteSendTime, 1ul << 24);
167     int64_t recv_time_diff =
168         new_packet.log_time_us() - old_packet.log_time_us();
169     double delay_change_us =
170         recv_time_diff - AbsSendTimeToMicroseconds(send_time_diff);
171     return delay_change_us / 1000;
172   } else {
173     return absl::nullopt;
174   }
175 }
176 
NetworkDelayDiff_CaptureTime(const LoggedRtpPacketIncoming & old_packet,const LoggedRtpPacketIncoming & new_packet,const double sample_rate)177 absl::optional<double> NetworkDelayDiff_CaptureTime(
178     const LoggedRtpPacketIncoming& old_packet,
179     const LoggedRtpPacketIncoming& new_packet,
180     const double sample_rate) {
181   int64_t send_time_diff =
182       WrappingDifference(new_packet.rtp.header.timestamp,
183                          old_packet.rtp.header.timestamp, 1ull << 32);
184   int64_t recv_time_diff = new_packet.log_time_us() - old_packet.log_time_us();
185 
186   double delay_change =
187       static_cast<double>(recv_time_diff) / 1000 -
188       static_cast<double>(send_time_diff) / sample_rate * 1000;
189   if (delay_change < -10000 || 10000 < delay_change) {
190     RTC_LOG(LS_WARNING) << "Very large delay change. Timestamps correct?";
191     RTC_LOG(LS_WARNING) << "Old capture time "
192                         << old_packet.rtp.header.timestamp << ", received time "
193                         << old_packet.log_time_us();
194     RTC_LOG(LS_WARNING) << "New capture time "
195                         << new_packet.rtp.header.timestamp << ", received time "
196                         << new_packet.log_time_us();
197     RTC_LOG(LS_WARNING) << "Receive time difference " << recv_time_diff << " = "
198                         << static_cast<double>(recv_time_diff) /
199                                kNumMicrosecsPerSec
200                         << "s";
201     RTC_LOG(LS_WARNING) << "Send time difference " << send_time_diff << " = "
202                         << static_cast<double>(send_time_diff) / sample_rate
203                         << "s";
204   }
205   return delay_change;
206 }
207 
208 
209 template <typename T>
CreateRtcpTypeTimeSeries(const std::vector<T> & rtcp_list,AnalyzerConfig config,std::string rtcp_name,int category_id)210 TimeSeries CreateRtcpTypeTimeSeries(const std::vector<T>& rtcp_list,
211                                     AnalyzerConfig config,
212                                     std::string rtcp_name,
213                                     int category_id) {
214   TimeSeries time_series(rtcp_name, LineStyle::kNone, PointStyle::kHighlight);
215   for (const auto& rtcp : rtcp_list) {
216     float x = config.GetCallTimeSec(rtcp.timestamp);
217     float y = category_id;
218     time_series.points.emplace_back(x, y);
219   }
220   return time_series;
221 }
222 
223 const char kUnknownEnumValue[] = "unknown";
224 
225 const char kIceCandidateTypeLocal[] = "local";
226 const char kIceCandidateTypeStun[] = "stun";
227 const char kIceCandidateTypePrflx[] = "prflx";
228 const char kIceCandidateTypeRelay[] = "relay";
229 
230 const char kProtocolUdp[] = "udp";
231 const char kProtocolTcp[] = "tcp";
232 const char kProtocolSsltcp[] = "ssltcp";
233 const char kProtocolTls[] = "tls";
234 
235 const char kAddressFamilyIpv4[] = "ipv4";
236 const char kAddressFamilyIpv6[] = "ipv6";
237 
238 const char kNetworkTypeEthernet[] = "ethernet";
239 const char kNetworkTypeLoopback[] = "loopback";
240 const char kNetworkTypeWifi[] = "wifi";
241 const char kNetworkTypeVpn[] = "vpn";
242 const char kNetworkTypeCellular[] = "cellular";
243 
GetIceCandidateTypeAsString(webrtc::IceCandidateType type)244 std::string GetIceCandidateTypeAsString(webrtc::IceCandidateType type) {
245   switch (type) {
246     case webrtc::IceCandidateType::kLocal:
247       return kIceCandidateTypeLocal;
248     case webrtc::IceCandidateType::kStun:
249       return kIceCandidateTypeStun;
250     case webrtc::IceCandidateType::kPrflx:
251       return kIceCandidateTypePrflx;
252     case webrtc::IceCandidateType::kRelay:
253       return kIceCandidateTypeRelay;
254     default:
255       return kUnknownEnumValue;
256   }
257 }
258 
GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol)259 std::string GetProtocolAsString(webrtc::IceCandidatePairProtocol protocol) {
260   switch (protocol) {
261     case webrtc::IceCandidatePairProtocol::kUdp:
262       return kProtocolUdp;
263     case webrtc::IceCandidatePairProtocol::kTcp:
264       return kProtocolTcp;
265     case webrtc::IceCandidatePairProtocol::kSsltcp:
266       return kProtocolSsltcp;
267     case webrtc::IceCandidatePairProtocol::kTls:
268       return kProtocolTls;
269     default:
270       return kUnknownEnumValue;
271   }
272 }
273 
GetAddressFamilyAsString(webrtc::IceCandidatePairAddressFamily family)274 std::string GetAddressFamilyAsString(
275     webrtc::IceCandidatePairAddressFamily family) {
276   switch (family) {
277     case webrtc::IceCandidatePairAddressFamily::kIpv4:
278       return kAddressFamilyIpv4;
279     case webrtc::IceCandidatePairAddressFamily::kIpv6:
280       return kAddressFamilyIpv6;
281     default:
282       return kUnknownEnumValue;
283   }
284 }
285 
GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type)286 std::string GetNetworkTypeAsString(webrtc::IceCandidateNetworkType type) {
287   switch (type) {
288     case webrtc::IceCandidateNetworkType::kEthernet:
289       return kNetworkTypeEthernet;
290     case webrtc::IceCandidateNetworkType::kLoopback:
291       return kNetworkTypeLoopback;
292     case webrtc::IceCandidateNetworkType::kWifi:
293       return kNetworkTypeWifi;
294     case webrtc::IceCandidateNetworkType::kVpn:
295       return kNetworkTypeVpn;
296     case webrtc::IceCandidateNetworkType::kCellular:
297       return kNetworkTypeCellular;
298     default:
299       return kUnknownEnumValue;
300   }
301 }
302 
GetCandidatePairLogDescriptionAsString(const LoggedIceCandidatePairConfig & config)303 std::string GetCandidatePairLogDescriptionAsString(
304     const LoggedIceCandidatePairConfig& config) {
305   // Example: stun:wifi->relay(tcp):cellular@udp:ipv4
306   // represents a pair of a local server-reflexive candidate on a WiFi network
307   // and a remote relay candidate using TCP as the relay protocol on a cell
308   // network, when the candidate pair communicates over UDP using IPv4.
309   rtc::StringBuilder ss;
310   std::string local_candidate_type =
311       GetIceCandidateTypeAsString(config.local_candidate_type);
312   std::string remote_candidate_type =
313       GetIceCandidateTypeAsString(config.remote_candidate_type);
314   if (config.local_candidate_type == webrtc::IceCandidateType::kRelay) {
315     local_candidate_type +=
316         "(" + GetProtocolAsString(config.local_relay_protocol) + ")";
317   }
318   ss << local_candidate_type << ":"
319      << GetNetworkTypeAsString(config.local_network_type) << ":"
320      << GetAddressFamilyAsString(config.local_address_family) << "->"
321      << remote_candidate_type << ":"
322      << GetAddressFamilyAsString(config.remote_address_family) << "@"
323      << GetProtocolAsString(config.candidate_pair_protocol);
324   return ss.Release();
325 }
326 
GetDirectionAsString(PacketDirection direction)327 std::string GetDirectionAsString(PacketDirection direction) {
328   if (direction == kIncomingPacket) {
329     return "Incoming";
330   } else {
331     return "Outgoing";
332   }
333 }
334 
GetDirectionAsShortString(PacketDirection direction)335 std::string GetDirectionAsShortString(PacketDirection direction) {
336   if (direction == kIncomingPacket) {
337     return "In";
338   } else {
339     return "Out";
340   }
341 }
342 
343 }  // namespace
344 
EventLogAnalyzer(const ParsedRtcEventLog & log,bool normalize_time)345 EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
346                                    bool normalize_time)
347     : parsed_log_(log) {
348   config_.window_duration_ = TimeDelta::Millis(250);
349   config_.step_ = TimeDelta::Millis(10);
350   if (!log.start_log_events().empty()) {
351     config_.rtc_to_utc_offset_ = log.start_log_events()[0].utc_time() -
352                                  log.start_log_events()[0].log_time();
353   }
354   config_.normalize_time_ = normalize_time;
355   config_.begin_time_ = parsed_log_.first_timestamp();
356   config_.end_time_ = parsed_log_.last_timestamp();
357   if (config_.end_time_ < config_.begin_time_) {
358     RTC_LOG(LS_WARNING) << "No useful events in the log.";
359     config_.begin_time_ = config_.end_time_ = Timestamp::Zero();
360   }
361 
362   RTC_LOG(LS_INFO) << "Log is "
363                    << (parsed_log_.last_timestamp().ms() -
364                        parsed_log_.first_timestamp().ms()) /
365                           1000
366                    << " seconds long.";
367 }
368 
EventLogAnalyzer(const ParsedRtcEventLog & log,const AnalyzerConfig & config)369 EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log,
370                                    const AnalyzerConfig& config)
371     : parsed_log_(log), config_(config) {
372   RTC_LOG(LS_INFO) << "Log is "
373                    << (parsed_log_.last_timestamp().ms() -
374                        parsed_log_.first_timestamp().ms()) /
375                           1000
376                    << " seconds long.";
377 }
378 
379 class BitrateObserver : public RemoteBitrateObserver {
380  public:
BitrateObserver()381   BitrateObserver() : last_bitrate_bps_(0), bitrate_updated_(false) {}
382 
Update(NetworkControlUpdate update)383   void Update(NetworkControlUpdate update) {
384     if (update.target_rate) {
385       last_bitrate_bps_ = update.target_rate->target_rate.bps();
386       bitrate_updated_ = true;
387     }
388   }
389 
OnReceiveBitrateChanged(const std::vector<uint32_t> & ssrcs,uint32_t bitrate)390   void OnReceiveBitrateChanged(const std::vector<uint32_t>& ssrcs,
391                                uint32_t bitrate) override {}
392 
last_bitrate_bps() const393   uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
GetAndResetBitrateUpdated()394   bool GetAndResetBitrateUpdated() {
395     bool bitrate_updated = bitrate_updated_;
396     bitrate_updated_ = false;
397     return bitrate_updated;
398   }
399 
400  private:
401   uint32_t last_bitrate_bps_;
402   bool bitrate_updated_;
403 };
404 
CreatePacketGraph(PacketDirection direction,Plot * plot)405 void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
406                                          Plot* plot) {
407   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
408     // Filter on SSRC.
409     if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
410       continue;
411     }
412 
413     TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
414                            LineStyle::kBar);
415     auto GetPacketSize = [](const LoggedRtpPacket& packet) {
416       return absl::optional<float>(packet.total_length);
417     };
418     auto ToCallTime = [this](const LoggedRtpPacket& packet) {
419       return this->config_.GetCallTimeSec(packet.timestamp);
420     };
421     ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
422                                    stream.packet_view, &time_series);
423     plot->AppendTimeSeries(std::move(time_series));
424   }
425 
426   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
427                  "Time (s)", kLeftMargin, kRightMargin);
428   plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
429                           kTopMargin);
430   plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
431 }
432 
CreateRtcpTypeGraph(PacketDirection direction,Plot * plot)433 void EventLogAnalyzer::CreateRtcpTypeGraph(PacketDirection direction,
434                                            Plot* plot) {
435   plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
436       parsed_log_.transport_feedbacks(direction), config_, "TWCC", 1));
437   plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
438       parsed_log_.receiver_reports(direction), config_, "RR", 2));
439   plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
440       parsed_log_.sender_reports(direction), config_, "SR", 3));
441   plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(
442       parsed_log_.extended_reports(direction), config_, "XR", 4));
443   plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.nacks(direction),
444                                                   config_, "NACK", 5));
445   plot->AppendTimeSeries(CreateRtcpTypeTimeSeries(parsed_log_.rembs(direction),
446                                                   config_, "REMB", 6));
447   plot->AppendTimeSeries(
448       CreateRtcpTypeTimeSeries(parsed_log_.firs(direction), config_, "FIR", 7));
449   plot->AppendTimeSeries(
450       CreateRtcpTypeTimeSeries(parsed_log_.plis(direction), config_, "PLI", 8));
451   plot->AppendTimeSeries(
452       CreateRtcpTypeTimeSeries(parsed_log_.byes(direction), config_, "BYE", 9));
453   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
454                  "Time (s)", kLeftMargin, kRightMargin);
455   plot->SetSuggestedYAxis(0, 1, "RTCP type", kBottomMargin, kTopMargin);
456   plot->SetTitle(GetDirectionAsString(direction) + " RTCP packets");
457   plot->SetYAxisTickLabels({{1, "TWCC"},
458                             {2, "RR"},
459                             {3, "SR"},
460                             {4, "XR"},
461                             {5, "NACK"},
462                             {6, "REMB"},
463                             {7, "FIR"},
464                             {8, "PLI"},
465                             {9, "BYE"}});
466 }
467 
468 template <typename IterableType>
CreateAccumulatedPacketsTimeSeries(Plot * plot,const IterableType & packets,const std::string & label)469 void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries(
470     Plot* plot,
471     const IterableType& packets,
472     const std::string& label) {
473   TimeSeries time_series(label, LineStyle::kStep);
474   for (size_t i = 0; i < packets.size(); i++) {
475     float x = config_.GetCallTimeSec(packets[i].log_time());
476     time_series.points.emplace_back(x, i + 1);
477   }
478   plot->AppendTimeSeries(std::move(time_series));
479 }
480 
CreateAccumulatedPacketsGraph(PacketDirection direction,Plot * plot)481 void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction,
482                                                      Plot* plot) {
483   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
484     if (!MatchingSsrc(stream.ssrc, desired_ssrc_))
485       continue;
486     std::string label = std::string("RTP ") +
487                         GetStreamName(parsed_log_, direction, stream.ssrc);
488     CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label);
489   }
490   std::string label =
491       std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")";
492   if (direction == kIncomingPacket) {
493     CreateAccumulatedPacketsTimeSeries(
494         plot, parsed_log_.incoming_rtcp_packets(), label);
495   } else {
496     CreateAccumulatedPacketsTimeSeries(
497         plot, parsed_log_.outgoing_rtcp_packets(), label);
498   }
499 
500   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
501                  "Time (s)", kLeftMargin, kRightMargin);
502   plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
503   plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
504                  " RTP/RTCP packets");
505 }
506 
CreatePacketRateGraph(PacketDirection direction,Plot * plot)507 void EventLogAnalyzer::CreatePacketRateGraph(PacketDirection direction,
508                                              Plot* plot) {
509   auto CountPackets = [](auto packet) { return 1.0; };
510   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
511     // Filter on SSRC.
512     if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
513       continue;
514     }
515     TimeSeries time_series(
516         std::string("RTP ") +
517             GetStreamName(parsed_log_, direction, stream.ssrc),
518         LineStyle::kLine);
519     MovingAverage<LoggedRtpPacket, double>(CountPackets, stream.packet_view,
520                                            config_, &time_series);
521     plot->AppendTimeSeries(std::move(time_series));
522   }
523   TimeSeries time_series(
524       std::string("RTCP ") + "(" + GetDirectionAsShortString(direction) + ")",
525       LineStyle::kLine);
526   if (direction == kIncomingPacket) {
527     MovingAverage<LoggedRtcpPacketIncoming, double>(
528         CountPackets, parsed_log_.incoming_rtcp_packets(), config_,
529         &time_series);
530   } else {
531     MovingAverage<LoggedRtcpPacketOutgoing, double>(
532         CountPackets, parsed_log_.outgoing_rtcp_packets(), config_,
533         &time_series);
534   }
535   plot->AppendTimeSeries(std::move(time_series));
536 
537   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
538                  "Time (s)", kLeftMargin, kRightMargin);
539   plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
540                           kTopMargin);
541   plot->SetTitle("Rate of " + GetDirectionAsString(direction) +
542                  " RTP/RTCP packets");
543 }
544 
CreateTotalPacketRateGraph(PacketDirection direction,Plot * plot)545 void EventLogAnalyzer::CreateTotalPacketRateGraph(PacketDirection direction,
546                                                   Plot* plot) {
547   // Contains a log timestamp to enable counting logged events of different
548   // types using MovingAverage().
549   class LogTime {
550    public:
551     explicit LogTime(Timestamp log_time) : log_time_(log_time) {}
552     Timestamp log_time() const { return log_time_; }
553 
554    private:
555     Timestamp log_time_;
556   };
557   std::vector<LogTime> packet_times;
558   auto handle_rtp = [&](const LoggedRtpPacket& packet) {
559     packet_times.emplace_back(packet.log_time());
560   };
561   RtcEventProcessor process;
562   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
563     process.AddEvents(stream.packet_view, handle_rtp);
564   }
565   if (direction == kIncomingPacket) {
566     auto handle_incoming_rtcp = [&](const LoggedRtcpPacketIncoming& packet) {
567       packet_times.emplace_back(packet.log_time());
568     };
569     process.AddEvents(parsed_log_.incoming_rtcp_packets(),
570                       handle_incoming_rtcp);
571   } else {
572     auto handle_outgoing_rtcp = [&](const LoggedRtcpPacketOutgoing& packet) {
573       packet_times.emplace_back(packet.log_time());
574     };
575     process.AddEvents(parsed_log_.outgoing_rtcp_packets(),
576                       handle_outgoing_rtcp);
577   }
578   process.ProcessEventsInOrder();
579   TimeSeries time_series(std::string("Total ") + "(" +
580                              GetDirectionAsShortString(direction) + ") packets",
581                          LineStyle::kLine);
582   MovingAverage<LogTime, uint64_t>([](auto packet) { return 1; }, packet_times,
583                                    config_, &time_series);
584   plot->AppendTimeSeries(std::move(time_series));
585 
586   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
587                  "Time (s)", kLeftMargin, kRightMargin);
588   plot->SetSuggestedYAxis(0, 1, "Packet Rate (packets/s)", kBottomMargin,
589                           kTopMargin);
590   plot->SetTitle("Rate of all " + GetDirectionAsString(direction) +
591                  " RTP/RTCP packets");
592 }
593 
594 // For each SSRC, plot the time between the consecutive playouts.
CreatePlayoutGraph(Plot * plot)595 void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) {
596   for (const auto& playout_stream : parsed_log_.audio_playout_events()) {
597     uint32_t ssrc = playout_stream.first;
598     if (!MatchingSsrc(ssrc, desired_ssrc_))
599       continue;
600     absl::optional<int64_t> last_playout_ms;
601     TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
602     for (const auto& playout_event : playout_stream.second) {
603       float x = config_.GetCallTimeSec(playout_event.log_time());
604       int64_t playout_time_ms = playout_event.log_time_ms();
605       // If there were no previous playouts, place the point on the x-axis.
606       float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
607       time_series.points.push_back(TimeSeriesPoint(x, y));
608       last_playout_ms.emplace(playout_time_ms);
609     }
610     plot->AppendTimeSeries(std::move(time_series));
611   }
612 
613   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
614                  "Time (s)", kLeftMargin, kRightMargin);
615   plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
616                           kTopMargin);
617   plot->SetTitle("Audio playout");
618 }
619 
620 // For audio SSRCs, plot the audio level.
CreateAudioLevelGraph(PacketDirection direction,Plot * plot)621 void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction,
622                                              Plot* plot) {
623   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
624     if (!IsAudioSsrc(parsed_log_, direction, stream.ssrc))
625       continue;
626     TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
627                            LineStyle::kLine);
628     for (auto& packet : stream.packet_view) {
629       if (packet.header.extension.hasAudioLevel) {
630         float x = config_.GetCallTimeSec(packet.log_time());
631         // The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
632         // Here we convert it to dBov.
633         float y = static_cast<float>(-packet.header.extension.audioLevel);
634         time_series.points.emplace_back(TimeSeriesPoint(x, y));
635       }
636     }
637     plot->AppendTimeSeries(std::move(time_series));
638   }
639 
640   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
641                  "Time (s)", kLeftMargin, kRightMargin);
642   plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin, kTopMargin);
643   plot->SetTitle(GetDirectionAsString(direction) + " audio level");
644 }
645 
646 // For each SSRC, plot the sequence number difference between consecutive
647 // incoming packets.
CreateSequenceNumberGraph(Plot * plot)648 void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) {
649   for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
650     // Filter on SSRC.
651     if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
652       continue;
653     }
654 
655     TimeSeries time_series(
656         GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc),
657         LineStyle::kBar);
658     auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet,
659                                     const LoggedRtpPacketIncoming& new_packet) {
660       int64_t diff =
661           WrappingDifference(new_packet.rtp.header.sequenceNumber,
662                              old_packet.rtp.header.sequenceNumber, 1ul << 16);
663       return diff;
664     };
665     auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
666       return this->config_.GetCallTimeSec(packet.log_time());
667     };
668     ProcessPairs<LoggedRtpPacketIncoming, float>(
669         ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
670         &time_series);
671     plot->AppendTimeSeries(std::move(time_series));
672   }
673 
674   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
675                  "Time (s)", kLeftMargin, kRightMargin);
676   plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
677                           kTopMargin);
678   plot->SetTitle("Incoming sequence number delta");
679 }
680 
CreateIncomingPacketLossGraph(Plot * plot)681 void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) {
682   for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
683     const std::vector<LoggedRtpPacketIncoming>& packets =
684         stream.incoming_packets;
685     // Filter on SSRC.
686     if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || packets.empty()) {
687       continue;
688     }
689 
690     TimeSeries time_series(
691         GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc),
692         LineStyle::kLine, PointStyle::kHighlight);
693     // TODO(terelius): Should the window and step size be read from the class
694     // instead?
695     const TimeDelta kWindow = TimeDelta::Millis(1000);
696     const TimeDelta kStep = TimeDelta::Millis(1000);
697     SeqNumUnwrapper<uint16_t> unwrapper_;
698     SeqNumUnwrapper<uint16_t> prior_unwrapper_;
699     size_t window_index_begin = 0;
700     size_t window_index_end = 0;
701     uint64_t highest_seq_number =
702         unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
703     uint64_t highest_prior_seq_number =
704         prior_unwrapper_.Unwrap(packets[0].rtp.header.sequenceNumber) - 1;
705 
706     for (Timestamp t = config_.begin_time_; t < config_.end_time_ + kStep;
707          t += kStep) {
708       while (window_index_end < packets.size() &&
709              packets[window_index_end].rtp.log_time() < t) {
710         uint64_t sequence_number = unwrapper_.Unwrap(
711             packets[window_index_end].rtp.header.sequenceNumber);
712         highest_seq_number = std::max(highest_seq_number, sequence_number);
713         ++window_index_end;
714       }
715       while (window_index_begin < packets.size() &&
716              packets[window_index_begin].rtp.log_time() < t - kWindow) {
717         uint64_t sequence_number = prior_unwrapper_.Unwrap(
718             packets[window_index_begin].rtp.header.sequenceNumber);
719         highest_prior_seq_number =
720             std::max(highest_prior_seq_number, sequence_number);
721         ++window_index_begin;
722       }
723       float x = config_.GetCallTimeSec(t);
724       uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
725       if (expected_packets > 0) {
726         int64_t received_packets = window_index_end - window_index_begin;
727         int64_t lost_packets = expected_packets - received_packets;
728         float y = static_cast<float>(lost_packets) / expected_packets * 100;
729         time_series.points.emplace_back(x, y);
730       }
731     }
732     plot->AppendTimeSeries(std::move(time_series));
733   }
734 
735   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
736                  "Time (s)", kLeftMargin, kRightMargin);
737   plot->SetSuggestedYAxis(0, 1, "Loss rate (in %)", kBottomMargin, kTopMargin);
738   plot->SetTitle("Incoming packet loss (derived from incoming packets)");
739 }
740 
CreateIncomingDelayGraph(Plot * plot)741 void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) {
742   for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
743     // Filter on SSRC.
744     if (!MatchingSsrc(stream.ssrc, desired_ssrc_) ||
745         IsRtxSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) {
746       continue;
747     }
748 
749     const std::vector<LoggedRtpPacketIncoming>& packets =
750         stream.incoming_packets;
751     if (packets.size() < 100) {
752       RTC_LOG(LS_WARNING) << "Can't estimate the RTP clock frequency with "
753                           << packets.size() << " packets in the stream.";
754       continue;
755     }
756     int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
757     absl::optional<uint32_t> estimated_frequency =
758         EstimateRtpClockFrequency(packets, segment_end_us);
759     if (!estimated_frequency)
760       continue;
761     const double frequency_hz = *estimated_frequency;
762     if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc) &&
763         frequency_hz != 90000) {
764       RTC_LOG(LS_WARNING)
765           << "Video stream should use a 90 kHz clock but appears to use "
766           << frequency_hz / 1000 << ". Discarding.";
767       continue;
768     }
769 
770     auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
771       return this->config_.GetCallTimeSec(packet.log_time());
772     };
773     auto ToNetworkDelay = [frequency_hz](
774                               const LoggedRtpPacketIncoming& old_packet,
775                               const LoggedRtpPacketIncoming& new_packet) {
776       return NetworkDelayDiff_CaptureTime(old_packet, new_packet, frequency_hz);
777     };
778 
779     TimeSeries capture_time_data(
780         GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) +
781             " capture-time",
782         LineStyle::kLine);
783     AccumulatePairs<LoggedRtpPacketIncoming, double>(
784         ToCallTime, ToNetworkDelay, packets, &capture_time_data);
785     plot->AppendTimeSeries(std::move(capture_time_data));
786 
787     TimeSeries send_time_data(
788         GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) +
789             " abs-send-time",
790         LineStyle::kLine);
791     AccumulatePairs<LoggedRtpPacketIncoming, double>(
792         ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data);
793     plot->AppendTimeSeriesIfNotEmpty(std::move(send_time_data));
794   }
795 
796   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
797                  "Time (s)", kLeftMargin, kRightMargin);
798   plot->SetSuggestedYAxis(0, 1, "Delay (ms)", kBottomMargin, kTopMargin);
799   plot->SetTitle("Incoming network delay (relative to first packet)");
800 }
801 
802 // Plot the fraction of packets lost (as perceived by the loss-based BWE).
CreateFractionLossGraph(Plot * plot)803 void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) {
804   TimeSeries time_series("Fraction lost", LineStyle::kLine,
805                          PointStyle::kHighlight);
806   for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
807     float x = config_.GetCallTimeSec(bwe_update.log_time());
808     float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
809     time_series.points.emplace_back(x, y);
810   }
811 
812   plot->AppendTimeSeries(std::move(time_series));
813   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
814                  "Time (s)", kLeftMargin, kRightMargin);
815   plot->SetSuggestedYAxis(0, 10, "Loss rate (in %)", kBottomMargin, kTopMargin);
816   plot->SetTitle("Outgoing packet loss (as reported by BWE)");
817 }
818 
819 // Plot the total bandwidth used by all RTP streams.
CreateTotalIncomingBitrateGraph(Plot * plot)820 void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) {
821   // TODO(terelius): This could be provided by the parser.
822   std::multimap<Timestamp, size_t> packets_in_order;
823   for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
824     for (const LoggedRtpPacketIncoming& packet : stream.incoming_packets)
825       packets_in_order.insert(
826           std::make_pair(packet.rtp.log_time(), packet.rtp.total_length));
827   }
828 
829   auto window_begin = packets_in_order.begin();
830   auto window_end = packets_in_order.begin();
831   size_t bytes_in_window = 0;
832 
833   if (!packets_in_order.empty()) {
834     // Calculate a moving average of the bitrate and store in a TimeSeries.
835     TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
836     for (Timestamp time = config_.begin_time_;
837          time < config_.end_time_ + config_.step_; time += config_.step_) {
838       while (window_end != packets_in_order.end() && window_end->first < time) {
839         bytes_in_window += window_end->second;
840         ++window_end;
841       }
842       while (window_begin != packets_in_order.end() &&
843              window_begin->first < time - config_.window_duration_) {
844         RTC_DCHECK_LE(window_begin->second, bytes_in_window);
845         bytes_in_window -= window_begin->second;
846         ++window_begin;
847       }
848       float window_duration_in_seconds =
849           static_cast<float>(config_.window_duration_.us()) /
850           kNumMicrosecsPerSec;
851       float x = config_.GetCallTimeSec(time);
852       float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
853       bitrate_series.points.emplace_back(x, y);
854     }
855     plot->AppendTimeSeries(std::move(bitrate_series));
856   }
857 
858   // Overlay the outgoing REMB over incoming bitrate.
859   TimeSeries remb_series("Remb", LineStyle::kStep);
860   for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
861     float x = config_.GetCallTimeSec(rtcp.log_time());
862     float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
863     remb_series.points.emplace_back(x, y);
864   }
865   plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
866 
867   if (!parsed_log_.generic_packets_received().empty()) {
868     TimeSeries time_series("Incoming generic bitrate", LineStyle::kLine);
869     auto GetPacketSizeKilobits = [](const LoggedGenericPacketReceived& packet) {
870       return packet.packet_length * 8.0 / 1000.0;
871     };
872     MovingAverage<LoggedGenericPacketReceived, double>(
873         GetPacketSizeKilobits, parsed_log_.generic_packets_received(), config_,
874         &time_series);
875     plot->AppendTimeSeries(std::move(time_series));
876   }
877 
878   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
879                  "Time (s)", kLeftMargin, kRightMargin);
880   plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
881   plot->SetTitle("Incoming RTP bitrate");
882 }
883 
884 // Plot the total bandwidth used by all RTP streams.
CreateTotalOutgoingBitrateGraph(Plot * plot,bool show_detector_state,bool show_alr_state,bool show_link_capacity)885 void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(
886     Plot* plot,
887     bool show_detector_state,
888     bool show_alr_state,
889     bool show_link_capacity) {
890   // TODO(terelius): This could be provided by the parser.
891   std::multimap<Timestamp, size_t> packets_in_order;
892   for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
893     for (const LoggedRtpPacketOutgoing& packet : stream.outgoing_packets)
894       packets_in_order.insert(
895           std::make_pair(packet.rtp.log_time(), packet.rtp.total_length));
896   }
897 
898   auto window_begin = packets_in_order.begin();
899   auto window_end = packets_in_order.begin();
900   size_t bytes_in_window = 0;
901 
902   if (!packets_in_order.empty()) {
903     // Calculate a moving average of the bitrate and store in a TimeSeries.
904     TimeSeries bitrate_series("Bitrate", LineStyle::kLine);
905     for (Timestamp time = config_.begin_time_;
906          time < config_.end_time_ + config_.step_; time += config_.step_) {
907       while (window_end != packets_in_order.end() && window_end->first < time) {
908         bytes_in_window += window_end->second;
909         ++window_end;
910       }
911       while (window_begin != packets_in_order.end() &&
912              window_begin->first < time - config_.window_duration_) {
913         RTC_DCHECK_LE(window_begin->second, bytes_in_window);
914         bytes_in_window -= window_begin->second;
915         ++window_begin;
916       }
917       float window_duration_in_seconds =
918           static_cast<float>(config_.window_duration_.us()) /
919           kNumMicrosecsPerSec;
920       float x = config_.GetCallTimeSec(time);
921       float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
922       bitrate_series.points.emplace_back(x, y);
923     }
924     plot->AppendTimeSeries(std::move(bitrate_series));
925   }
926 
927   // Overlay the send-side bandwidth estimate over the outgoing bitrate.
928   TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
929   for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
930     float x = config_.GetCallTimeSec(loss_update.log_time());
931     float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
932     loss_series.points.emplace_back(x, y);
933   }
934 
935   TimeSeries link_capacity_lower_series("Link-capacity-lower",
936                                         LineStyle::kStep);
937   TimeSeries link_capacity_upper_series("Link-capacity-upper",
938                                         LineStyle::kStep);
939   for (auto& remote_estimate_event : parsed_log_.remote_estimate_events()) {
940     float x = config_.GetCallTimeSec(remote_estimate_event.log_time());
941     if (remote_estimate_event.link_capacity_lower.has_value()) {
942       float link_capacity_lower = static_cast<float>(
943           remote_estimate_event.link_capacity_lower.value().kbps());
944       link_capacity_lower_series.points.emplace_back(x, link_capacity_lower);
945     }
946     if (remote_estimate_event.link_capacity_upper.has_value()) {
947       float link_capacity_upper = static_cast<float>(
948           remote_estimate_event.link_capacity_upper.value().kbps());
949       link_capacity_upper_series.points.emplace_back(x, link_capacity_upper);
950     }
951   }
952 
953   TimeSeries delay_series("Delay-based estimate", LineStyle::kStep);
954   IntervalSeries overusing_series("Overusing", "#ff8e82",
955                                   IntervalSeries::kHorizontal);
956   IntervalSeries underusing_series("Underusing", "#5092fc",
957                                    IntervalSeries::kHorizontal);
958   IntervalSeries normal_series("Normal", "#c4ffc4",
959                                IntervalSeries::kHorizontal);
960   IntervalSeries* last_series = &normal_series;
961   float last_detector_switch = 0.0;
962 
963   BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
964 
965   for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
966     float x = config_.GetCallTimeSec(delay_update.log_time());
967     float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
968 
969     if (last_detector_state != delay_update.detector_state) {
970       last_series->intervals.emplace_back(last_detector_switch, x);
971       last_detector_state = delay_update.detector_state;
972       last_detector_switch = x;
973 
974       switch (delay_update.detector_state) {
975         case BandwidthUsage::kBwNormal:
976           last_series = &normal_series;
977           break;
978         case BandwidthUsage::kBwUnderusing:
979           last_series = &underusing_series;
980           break;
981         case BandwidthUsage::kBwOverusing:
982           last_series = &overusing_series;
983           break;
984         case BandwidthUsage::kLast:
985           RTC_DCHECK_NOTREACHED();
986       }
987     }
988 
989     delay_series.points.emplace_back(x, y);
990   }
991 
992   RTC_CHECK(last_series);
993   last_series->intervals.emplace_back(last_detector_switch,
994                                       config_.CallEndTimeSec());
995 
996   TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
997                             PointStyle::kHighlight);
998   for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
999     float x = config_.GetCallTimeSec(cluster.log_time());
1000     float y = static_cast<float>(cluster.bitrate_bps) / 1000;
1001     created_series.points.emplace_back(x, y);
1002   }
1003 
1004   TimeSeries result_series("Probing results.", LineStyle::kNone,
1005                            PointStyle::kHighlight);
1006   for (auto& result : parsed_log_.bwe_probe_success_events()) {
1007     float x = config_.GetCallTimeSec(result.log_time());
1008     float y = static_cast<float>(result.bitrate_bps) / 1000;
1009     result_series.points.emplace_back(x, y);
1010   }
1011 
1012   TimeSeries probe_failures_series("Probe failed", LineStyle::kNone,
1013                                    PointStyle::kHighlight);
1014   for (auto& failure : parsed_log_.bwe_probe_failure_events()) {
1015     float x = config_.GetCallTimeSec(failure.log_time());
1016     probe_failures_series.points.emplace_back(x, 0);
1017   }
1018 
1019   IntervalSeries alr_state("ALR", "#555555", IntervalSeries::kHorizontal);
1020   bool previously_in_alr = false;
1021   Timestamp alr_start = Timestamp::Zero();
1022   for (auto& alr : parsed_log_.alr_state_events()) {
1023     float y = config_.GetCallTimeSec(alr.log_time());
1024     if (!previously_in_alr && alr.in_alr) {
1025       alr_start = alr.log_time();
1026       previously_in_alr = true;
1027     } else if (previously_in_alr && !alr.in_alr) {
1028       float x = config_.GetCallTimeSec(alr_start);
1029       alr_state.intervals.emplace_back(x, y);
1030       previously_in_alr = false;
1031     }
1032   }
1033 
1034   if (previously_in_alr) {
1035     float x = config_.GetCallTimeSec(alr_start);
1036     float y = config_.GetCallTimeSec(config_.end_time_);
1037     alr_state.intervals.emplace_back(x, y);
1038   }
1039 
1040   if (show_detector_state) {
1041     plot->AppendIntervalSeries(std::move(overusing_series));
1042     plot->AppendIntervalSeries(std::move(underusing_series));
1043     plot->AppendIntervalSeries(std::move(normal_series));
1044   }
1045 
1046   if (show_alr_state) {
1047     plot->AppendIntervalSeries(std::move(alr_state));
1048   }
1049 
1050   if (show_link_capacity) {
1051     plot->AppendTimeSeriesIfNotEmpty(std::move(link_capacity_lower_series));
1052     plot->AppendTimeSeriesIfNotEmpty(std::move(link_capacity_upper_series));
1053   }
1054 
1055   plot->AppendTimeSeries(std::move(loss_series));
1056   plot->AppendTimeSeriesIfNotEmpty(std::move(probe_failures_series));
1057   plot->AppendTimeSeries(std::move(delay_series));
1058   plot->AppendTimeSeries(std::move(created_series));
1059   plot->AppendTimeSeries(std::move(result_series));
1060 
1061   // Overlay the incoming REMB over the outgoing bitrate.
1062   TimeSeries remb_series("Remb", LineStyle::kStep);
1063   for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
1064     float x = config_.GetCallTimeSec(rtcp.log_time());
1065     float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
1066     remb_series.points.emplace_back(x, y);
1067   }
1068   plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
1069 
1070   if (!parsed_log_.generic_packets_sent().empty()) {
1071     {
1072       TimeSeries time_series("Outgoing generic total bitrate",
1073                              LineStyle::kLine);
1074       auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1075         return packet.packet_length() * 8.0 / 1000.0;
1076       };
1077       MovingAverage<LoggedGenericPacketSent, double>(
1078           GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1079           &time_series);
1080       plot->AppendTimeSeries(std::move(time_series));
1081     }
1082 
1083     {
1084       TimeSeries time_series("Outgoing generic payload bitrate",
1085                              LineStyle::kLine);
1086       auto GetPacketSizeKilobits = [](const LoggedGenericPacketSent& packet) {
1087         return packet.payload_length * 8.0 / 1000.0;
1088       };
1089       MovingAverage<LoggedGenericPacketSent, double>(
1090           GetPacketSizeKilobits, parsed_log_.generic_packets_sent(), config_,
1091           &time_series);
1092       plot->AppendTimeSeries(std::move(time_series));
1093     }
1094   }
1095 
1096   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1097                  "Time (s)", kLeftMargin, kRightMargin);
1098   plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1099   plot->SetTitle("Outgoing RTP bitrate");
1100 }
1101 
1102 // For each SSRC, plot the bandwidth used by that stream.
CreateStreamBitrateGraph(PacketDirection direction,Plot * plot)1103 void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction,
1104                                                 Plot* plot) {
1105   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1106     // Filter on SSRC.
1107     if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) {
1108       continue;
1109     }
1110 
1111     TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc),
1112                            LineStyle::kLine);
1113     auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
1114       return packet.total_length * 8.0 / 1000.0;
1115     };
1116     MovingAverage<LoggedRtpPacket, double>(
1117         GetPacketSizeKilobits, stream.packet_view, config_, &time_series);
1118     plot->AppendTimeSeries(std::move(time_series));
1119   }
1120 
1121   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1122                  "Time (s)", kLeftMargin, kRightMargin);
1123   plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1124   plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
1125 }
1126 
1127 // Plot the bitrate allocation for each temporal and spatial layer.
1128 // Computed from RTCP XR target bitrate block, so the graph is only populated if
1129 // those are sent.
CreateBitrateAllocationGraph(PacketDirection direction,Plot * plot)1130 void EventLogAnalyzer::CreateBitrateAllocationGraph(PacketDirection direction,
1131                                                     Plot* plot) {
1132   std::map<LayerDescription, TimeSeries> time_series;
1133   const auto& xr_list = parsed_log_.extended_reports(direction);
1134   for (const auto& rtcp : xr_list) {
1135     const absl::optional<rtcp::TargetBitrate>& target_bitrate =
1136         rtcp.xr.target_bitrate();
1137     if (!target_bitrate.has_value())
1138       continue;
1139     for (const auto& bitrate_item : target_bitrate->GetTargetBitrates()) {
1140       LayerDescription layer(rtcp.xr.sender_ssrc(), bitrate_item.spatial_layer,
1141                              bitrate_item.temporal_layer);
1142       auto time_series_it = time_series.find(layer);
1143       if (time_series_it == time_series.end()) {
1144         std::string layer_name = GetLayerName(layer);
1145         bool inserted;
1146         std::tie(time_series_it, inserted) = time_series.insert(
1147             std::make_pair(layer, TimeSeries(layer_name, LineStyle::kStep)));
1148         RTC_DCHECK(inserted);
1149       }
1150       float x = config_.GetCallTimeSec(rtcp.log_time());
1151       float y = bitrate_item.target_bitrate_kbps;
1152       time_series_it->second.points.emplace_back(x, y);
1153     }
1154   }
1155   for (auto& layer : time_series) {
1156     plot->AppendTimeSeries(std::move(layer.second));
1157   }
1158   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1159                  "Time (s)", kLeftMargin, kRightMargin);
1160   plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1161   if (direction == kIncomingPacket)
1162     plot->SetTitle("Target bitrate per incoming layer");
1163   else
1164     plot->SetTitle("Target bitrate per outgoing layer");
1165 }
1166 
CreateGoogCcSimulationGraph(Plot * plot)1167 void EventLogAnalyzer::CreateGoogCcSimulationGraph(Plot* plot) {
1168   TimeSeries target_rates("Simulated target rate", LineStyle::kStep,
1169                           PointStyle::kHighlight);
1170   TimeSeries delay_based("Logged delay-based estimate", LineStyle::kStep,
1171                          PointStyle::kHighlight);
1172   TimeSeries loss_based("Logged loss-based estimate", LineStyle::kStep,
1173                         PointStyle::kHighlight);
1174   TimeSeries probe_results("Logged probe success", LineStyle::kNone,
1175                            PointStyle::kHighlight);
1176 
1177   LogBasedNetworkControllerSimulation simulation(
1178       std::make_unique<GoogCcNetworkControllerFactory>(),
1179       [&](const NetworkControlUpdate& update, Timestamp at_time) {
1180         if (update.target_rate) {
1181           target_rates.points.emplace_back(
1182               config_.GetCallTimeSec(at_time),
1183               update.target_rate->target_rate.kbps<float>());
1184         }
1185       });
1186 
1187   simulation.ProcessEventsInLog(parsed_log_);
1188   for (const auto& logged : parsed_log_.bwe_delay_updates())
1189     delay_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time()),
1190                                     logged.bitrate_bps / 1000);
1191   for (const auto& logged : parsed_log_.bwe_probe_success_events())
1192     probe_results.points.emplace_back(config_.GetCallTimeSec(logged.log_time()),
1193                                       logged.bitrate_bps / 1000);
1194   for (const auto& logged : parsed_log_.bwe_loss_updates())
1195     loss_based.points.emplace_back(config_.GetCallTimeSec(logged.log_time()),
1196                                    logged.bitrate_bps / 1000);
1197 
1198   plot->AppendTimeSeries(std::move(delay_based));
1199   plot->AppendTimeSeries(std::move(loss_based));
1200   plot->AppendTimeSeries(std::move(probe_results));
1201   plot->AppendTimeSeries(std::move(target_rates));
1202 
1203   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1204                  "Time (s)", kLeftMargin, kRightMargin);
1205   plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1206   plot->SetTitle("Simulated BWE behavior");
1207 }
1208 
CreateSendSideBweSimulationGraph(Plot * plot)1209 void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) {
1210   using RtpPacketType = LoggedRtpPacketOutgoing;
1211   using TransportFeedbackType = LoggedRtcpPacketTransportFeedback;
1212 
1213   // TODO(terelius): This could be provided by the parser.
1214   std::multimap<int64_t, const RtpPacketType*> outgoing_rtp;
1215   for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1216     for (const RtpPacketType& rtp_packet : stream.outgoing_packets)
1217       outgoing_rtp.insert(
1218           std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
1219   }
1220 
1221   const std::vector<TransportFeedbackType>& incoming_rtcp =
1222       parsed_log_.transport_feedbacks(kIncomingPacket);
1223 
1224   SimulatedClock clock(0);
1225   BitrateObserver observer;
1226   RtcEventLogNull null_event_log;
1227   TransportFeedbackAdapter transport_feedback;
1228   auto factory = GoogCcNetworkControllerFactory();
1229   TimeDelta process_interval = factory.GetProcessInterval();
1230   // TODO(holmer): Log the call config and use that here instead.
1231   static const uint32_t kDefaultStartBitrateBps = 300000;
1232   NetworkControllerConfig cc_config;
1233   cc_config.constraints.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
1234   cc_config.constraints.starting_rate =
1235       DataRate::BitsPerSec(kDefaultStartBitrateBps);
1236   cc_config.event_log = &null_event_log;
1237   auto goog_cc = factory.Create(cc_config);
1238 
1239   TimeSeries time_series("Delay-based estimate", LineStyle::kStep,
1240                          PointStyle::kHighlight);
1241   TimeSeries acked_time_series("Raw acked bitrate", LineStyle::kLine,
1242                                PointStyle::kHighlight);
1243   TimeSeries robust_time_series("Robust throughput estimate", LineStyle::kLine,
1244                                 PointStyle::kHighlight);
1245   TimeSeries acked_estimate_time_series("Ackednowledged bitrate estimate",
1246                                         LineStyle::kLine,
1247                                         PointStyle::kHighlight);
1248 
1249   auto rtp_iterator = outgoing_rtp.begin();
1250   auto rtcp_iterator = incoming_rtcp.begin();
1251 
1252   auto NextRtpTime = [&]() {
1253     if (rtp_iterator != outgoing_rtp.end())
1254       return static_cast<int64_t>(rtp_iterator->first);
1255     return std::numeric_limits<int64_t>::max();
1256   };
1257 
1258   auto NextRtcpTime = [&]() {
1259     if (rtcp_iterator != incoming_rtcp.end())
1260       return static_cast<int64_t>(rtcp_iterator->log_time_us());
1261     return std::numeric_limits<int64_t>::max();
1262   };
1263   int64_t next_process_time_us_ = std::min({NextRtpTime(), NextRtcpTime()});
1264 
1265   auto NextProcessTime = [&]() {
1266     if (rtcp_iterator != incoming_rtcp.end() ||
1267         rtp_iterator != outgoing_rtp.end()) {
1268       return next_process_time_us_;
1269     }
1270     return std::numeric_limits<int64_t>::max();
1271   };
1272 
1273   RateStatistics raw_acked_bitrate(750, 8000);
1274   test::ExplicitKeyValueConfig throughput_config(
1275       "WebRTC-Bwe-RobustThroughputEstimatorSettings/"
1276       "enabled:true,required_packets:10,"
1277       "window_packets:25,window_duration:1000ms,unacked_weight:1.0/");
1278   std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1279       robust_throughput_estimator(
1280           AcknowledgedBitrateEstimatorInterface::Create(&throughput_config));
1281   FieldTrialBasedConfig field_trial_config;
1282   std::unique_ptr<AcknowledgedBitrateEstimatorInterface>
1283       acknowledged_bitrate_estimator(
1284           AcknowledgedBitrateEstimatorInterface::Create(&field_trial_config));
1285   int64_t time_us =
1286       std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1287   int64_t last_update_us = 0;
1288   while (time_us != std::numeric_limits<int64_t>::max()) {
1289     clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds());
1290     if (clock.TimeInMicroseconds() >= NextRtpTime()) {
1291       RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime());
1292       const RtpPacketType& rtp_packet = *rtp_iterator->second;
1293       if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1294         RtpPacketSendInfo packet_info;
1295         packet_info.media_ssrc = rtp_packet.rtp.header.ssrc;
1296         packet_info.transport_sequence_number =
1297             rtp_packet.rtp.header.extension.transportSequenceNumber;
1298         packet_info.rtp_sequence_number = rtp_packet.rtp.header.sequenceNumber;
1299         packet_info.length = rtp_packet.rtp.total_length;
1300         if (IsRtxSsrc(parsed_log_, PacketDirection::kOutgoingPacket,
1301                       rtp_packet.rtp.header.ssrc)) {
1302           // Don't set the optional media type as we don't know if it is
1303           // a retransmission, FEC or padding.
1304         } else if (IsVideoSsrc(parsed_log_, PacketDirection::kOutgoingPacket,
1305                                rtp_packet.rtp.header.ssrc)) {
1306           packet_info.packet_type = RtpPacketMediaType::kVideo;
1307         } else if (IsAudioSsrc(parsed_log_, PacketDirection::kOutgoingPacket,
1308                                rtp_packet.rtp.header.ssrc)) {
1309           packet_info.packet_type = RtpPacketMediaType::kAudio;
1310         }
1311         transport_feedback.AddPacket(
1312             packet_info,
1313             0u,  // Per packet overhead bytes.
1314             Timestamp::Micros(rtp_packet.rtp.log_time_us()));
1315       }
1316       rtc::SentPacket sent_packet;
1317       sent_packet.send_time_ms = rtp_packet.rtp.log_time_ms();
1318       sent_packet.info.included_in_allocation = true;
1319       sent_packet.info.packet_size_bytes = rtp_packet.rtp.total_length;
1320       if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) {
1321         sent_packet.packet_id =
1322             rtp_packet.rtp.header.extension.transportSequenceNumber;
1323         sent_packet.info.included_in_feedback = true;
1324       }
1325       auto sent_msg = transport_feedback.ProcessSentPacket(sent_packet);
1326       if (sent_msg)
1327         observer.Update(goog_cc->OnSentPacket(*sent_msg));
1328       ++rtp_iterator;
1329     }
1330     if (clock.TimeInMicroseconds() >= NextRtcpTime()) {
1331       RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime());
1332 
1333       auto feedback_msg = transport_feedback.ProcessTransportFeedback(
1334           rtcp_iterator->transport_feedback,
1335           Timestamp::Millis(clock.TimeInMilliseconds()));
1336       if (feedback_msg) {
1337         observer.Update(goog_cc->OnTransportPacketsFeedback(*feedback_msg));
1338         std::vector<PacketResult> feedback =
1339             feedback_msg->SortedByReceiveTime();
1340         if (!feedback.empty()) {
1341           acknowledged_bitrate_estimator->IncomingPacketFeedbackVector(
1342               feedback);
1343           robust_throughput_estimator->IncomingPacketFeedbackVector(feedback);
1344           for (const PacketResult& packet : feedback) {
1345             raw_acked_bitrate.Update(packet.sent_packet.size.bytes(),
1346                                      packet.receive_time.ms());
1347           }
1348           absl::optional<uint32_t> raw_bitrate_bps =
1349               raw_acked_bitrate.Rate(feedback.back().receive_time.ms());
1350           float x = config_.GetCallTimeSec(clock.CurrentTime());
1351           if (raw_bitrate_bps) {
1352             float y = raw_bitrate_bps.value() / 1000;
1353             acked_time_series.points.emplace_back(x, y);
1354           }
1355           absl::optional<DataRate> robust_estimate =
1356               robust_throughput_estimator->bitrate();
1357           if (robust_estimate) {
1358             float y = robust_estimate.value().kbps();
1359             robust_time_series.points.emplace_back(x, y);
1360           }
1361           absl::optional<DataRate> acked_estimate =
1362               acknowledged_bitrate_estimator->bitrate();
1363           if (acked_estimate) {
1364             float y = acked_estimate.value().kbps();
1365             acked_estimate_time_series.points.emplace_back(x, y);
1366           }
1367         }
1368       }
1369       ++rtcp_iterator;
1370     }
1371     if (clock.TimeInMicroseconds() >= NextProcessTime()) {
1372       RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextProcessTime());
1373       ProcessInterval msg;
1374       msg.at_time = Timestamp::Micros(clock.TimeInMicroseconds());
1375       observer.Update(goog_cc->OnProcessInterval(msg));
1376       next_process_time_us_ += process_interval.us();
1377     }
1378     if (observer.GetAndResetBitrateUpdated() ||
1379         time_us - last_update_us >= 1e6) {
1380       uint32_t y = observer.last_bitrate_bps() / 1000;
1381       float x = config_.GetCallTimeSec(clock.CurrentTime());
1382       time_series.points.emplace_back(x, y);
1383       last_update_us = time_us;
1384     }
1385     time_us = std::min({NextRtpTime(), NextRtcpTime(), NextProcessTime()});
1386   }
1387   // Add the data set to the plot.
1388   plot->AppendTimeSeries(std::move(time_series));
1389   plot->AppendTimeSeries(std::move(robust_time_series));
1390   plot->AppendTimeSeries(std::move(acked_time_series));
1391   plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
1392 
1393   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1394                  "Time (s)", kLeftMargin, kRightMargin);
1395   plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1396   plot->SetTitle("Simulated send-side BWE behavior");
1397 }
1398 
CreateReceiveSideBweSimulationGraph(Plot * plot)1399 void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) {
1400   using RtpPacketType = LoggedRtpPacketIncoming;
1401   class RembInterceptor {
1402    public:
1403     void SendRemb(uint32_t bitrate_bps, std::vector<uint32_t> ssrcs) {
1404       last_bitrate_bps_ = bitrate_bps;
1405       bitrate_updated_ = true;
1406     }
1407     uint32_t last_bitrate_bps() const { return last_bitrate_bps_; }
1408     bool GetAndResetBitrateUpdated() {
1409       bool bitrate_updated = bitrate_updated_;
1410       bitrate_updated_ = false;
1411       return bitrate_updated;
1412     }
1413 
1414    private:
1415     // We don't know the start bitrate, but assume that it is the default 300
1416     // kbps.
1417     uint32_t last_bitrate_bps_ = 300000;
1418     bool bitrate_updated_ = false;
1419   };
1420 
1421   std::multimap<int64_t, const RtpPacketType*> incoming_rtp;
1422 
1423   for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) {
1424     if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) {
1425       for (const auto& rtp_packet : stream.incoming_packets)
1426         incoming_rtp.insert(
1427             std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet));
1428     }
1429   }
1430 
1431   SimulatedClock clock(0);
1432   RembInterceptor remb_interceptor;
1433   ReceiveSideCongestionController rscc(
1434       &clock, [](auto...) {},
1435       absl::bind_front(&RembInterceptor::SendRemb, &remb_interceptor), nullptr);
1436   // TODO(holmer): Log the call config and use that here instead.
1437   // static const uint32_t kDefaultStartBitrateBps = 300000;
1438   // rscc.SetBweBitrates(0, kDefaultStartBitrateBps, -1);
1439 
1440   TimeSeries time_series("Receive side estimate", LineStyle::kLine,
1441                          PointStyle::kHighlight);
1442   TimeSeries acked_time_series("Received bitrate", LineStyle::kLine);
1443 
1444   RateStatistics acked_bitrate(250, 8000);
1445   int64_t last_update_us = 0;
1446   for (const auto& kv : incoming_rtp) {
1447     const RtpPacketType& packet = *kv.second;
1448     int64_t arrival_time_ms = packet.rtp.log_time_us() / 1000;
1449     size_t payload = packet.rtp.total_length; /*Should subtract header?*/
1450     clock.AdvanceTimeMicroseconds(packet.rtp.log_time_us() -
1451                                   clock.TimeInMicroseconds());
1452     rscc.OnReceivedPacket(arrival_time_ms, payload, packet.rtp.header);
1453     acked_bitrate.Update(payload, arrival_time_ms);
1454     absl::optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
1455     if (bitrate_bps) {
1456       uint32_t y = *bitrate_bps / 1000;
1457       float x = config_.GetCallTimeSec(clock.CurrentTime());
1458       acked_time_series.points.emplace_back(x, y);
1459     }
1460     if (remb_interceptor.GetAndResetBitrateUpdated() ||
1461         clock.TimeInMicroseconds() - last_update_us >= 1e6) {
1462       uint32_t y = remb_interceptor.last_bitrate_bps() / 1000;
1463       float x = config_.GetCallTimeSec(clock.CurrentTime());
1464       time_series.points.emplace_back(x, y);
1465       last_update_us = clock.TimeInMicroseconds();
1466     }
1467   }
1468   // Add the data set to the plot.
1469   plot->AppendTimeSeries(std::move(time_series));
1470   plot->AppendTimeSeries(std::move(acked_time_series));
1471 
1472   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1473                  "Time (s)", kLeftMargin, kRightMargin);
1474   plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
1475   plot->SetTitle("Simulated receive-side BWE behavior");
1476 }
1477 
CreateNetworkDelayFeedbackGraph(Plot * plot)1478 void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) {
1479   TimeSeries time_series("Network delay", LineStyle::kLine,
1480                          PointStyle::kHighlight);
1481   int64_t min_send_receive_diff_ms = std::numeric_limits<int64_t>::max();
1482   int64_t min_rtt_ms = std::numeric_limits<int64_t>::max();
1483 
1484   std::vector<MatchedSendArrivalTimes> matched_rtp_rtcp =
1485       GetNetworkTrace(parsed_log_);
1486   absl::c_stable_sort(matched_rtp_rtcp, [](const MatchedSendArrivalTimes& a,
1487                                            const MatchedSendArrivalTimes& b) {
1488     return a.feedback_arrival_time_ms < b.feedback_arrival_time_ms ||
1489            (a.feedback_arrival_time_ms == b.feedback_arrival_time_ms &&
1490             a.arrival_time_ms < b.arrival_time_ms);
1491   });
1492   for (const auto& packet : matched_rtp_rtcp) {
1493     if (packet.arrival_time_ms == MatchedSendArrivalTimes::kNotReceived)
1494       continue;
1495     float x = config_.GetCallTimeSecFromMs(packet.feedback_arrival_time_ms);
1496     int64_t y = packet.arrival_time_ms - packet.send_time_ms;
1497     int64_t rtt_ms = packet.feedback_arrival_time_ms - packet.send_time_ms;
1498     min_rtt_ms = std::min(rtt_ms, min_rtt_ms);
1499     min_send_receive_diff_ms = std::min(y, min_send_receive_diff_ms);
1500     time_series.points.emplace_back(x, y);
1501   }
1502 
1503   // We assume that the base network delay (w/o queues) is equal to half
1504   // the minimum RTT. Therefore rescale the delays by subtracting the minimum
1505   // observed 1-ways delay and add half the minimum RTT.
1506   const int64_t estimated_clock_offset_ms =
1507       min_send_receive_diff_ms - min_rtt_ms / 2;
1508   for (TimeSeriesPoint& point : time_series.points)
1509     point.y -= estimated_clock_offset_ms;
1510 
1511   // Add the data set to the plot.
1512   plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
1513 
1514   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1515                  "Time (s)", kLeftMargin, kRightMargin);
1516   plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
1517   plot->SetTitle("Outgoing network delay (based on per-packet feedback)");
1518 }
1519 
CreatePacerDelayGraph(Plot * plot)1520 void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
1521   for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) {
1522     const std::vector<LoggedRtpPacketOutgoing>& packets =
1523         stream.outgoing_packets;
1524 
1525     if (IsRtxSsrc(parsed_log_, kOutgoingPacket, stream.ssrc)) {
1526       continue;
1527     }
1528 
1529     if (packets.size() < 2) {
1530       RTC_LOG(LS_WARNING)
1531           << "Can't estimate a the RTP clock frequency or the "
1532              "pacer delay with less than 2 packets in the stream";
1533       continue;
1534     }
1535     int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
1536     absl::optional<uint32_t> estimated_frequency =
1537         EstimateRtpClockFrequency(packets, segment_end_us);
1538     if (!estimated_frequency)
1539       continue;
1540     if (IsVideoSsrc(parsed_log_, kOutgoingPacket, stream.ssrc) &&
1541         *estimated_frequency != 90000) {
1542       RTC_LOG(LS_WARNING)
1543           << "Video stream should use a 90 kHz clock but appears to use "
1544           << *estimated_frequency / 1000 << ". Discarding.";
1545       continue;
1546     }
1547 
1548     TimeSeries pacer_delay_series(
1549         GetStreamName(parsed_log_, kOutgoingPacket, stream.ssrc) + "(" +
1550             std::to_string(*estimated_frequency / 1000) + " kHz)",
1551         LineStyle::kLine, PointStyle::kHighlight);
1552     SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
1553     uint64_t first_capture_timestamp =
1554         timestamp_unwrapper.Unwrap(packets.front().rtp.header.timestamp);
1555     uint64_t first_send_timestamp = packets.front().rtp.log_time_us();
1556     for (const auto& packet : packets) {
1557       double capture_time_ms = (static_cast<double>(timestamp_unwrapper.Unwrap(
1558                                     packet.rtp.header.timestamp)) -
1559                                 first_capture_timestamp) /
1560                                *estimated_frequency * 1000;
1561       double send_time_ms =
1562           static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1563           1000;
1564       float x = config_.GetCallTimeSec(packet.rtp.log_time());
1565       float y = send_time_ms - capture_time_ms;
1566       pacer_delay_series.points.emplace_back(x, y);
1567     }
1568     plot->AppendTimeSeries(std::move(pacer_delay_series));
1569   }
1570 
1571   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1572                  "Time (s)", kLeftMargin, kRightMargin);
1573   plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
1574   plot->SetTitle(
1575       "Delay from capture to send time. (First packet normalized to 0.)");
1576 }
1577 
CreateTimestampGraph(PacketDirection direction,Plot * plot)1578 void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction,
1579                                             Plot* plot) {
1580   for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) {
1581     TimeSeries rtp_timestamps(
1582         GetStreamName(parsed_log_, direction, stream.ssrc) + " capture-time",
1583         LineStyle::kLine, PointStyle::kHighlight);
1584     for (const auto& packet : stream.packet_view) {
1585       float x = config_.GetCallTimeSec(packet.log_time());
1586       float y = packet.header.timestamp;
1587       rtp_timestamps.points.emplace_back(x, y);
1588     }
1589     plot->AppendTimeSeries(std::move(rtp_timestamps));
1590 
1591     TimeSeries rtcp_timestamps(
1592         GetStreamName(parsed_log_, direction, stream.ssrc) +
1593             " rtcp capture-time",
1594         LineStyle::kLine, PointStyle::kHighlight);
1595     // TODO(terelius): Why only sender reports?
1596     const auto& sender_reports = parsed_log_.sender_reports(direction);
1597     for (const auto& rtcp : sender_reports) {
1598       if (rtcp.sr.sender_ssrc() != stream.ssrc)
1599         continue;
1600       float x = config_.GetCallTimeSec(rtcp.log_time());
1601       float y = rtcp.sr.rtp_timestamp();
1602       rtcp_timestamps.points.emplace_back(x, y);
1603     }
1604     plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
1605   }
1606 
1607   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1608                  "Time (s)", kLeftMargin, kRightMargin);
1609   plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
1610   plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
1611 }
1612 
CreateSenderAndReceiverReportPlot(PacketDirection direction,rtc::FunctionView<float (const rtcp::ReportBlock &)> fy,std::string title,std::string yaxis_label,Plot * plot)1613 void EventLogAnalyzer::CreateSenderAndReceiverReportPlot(
1614     PacketDirection direction,
1615     rtc::FunctionView<float(const rtcp::ReportBlock&)> fy,
1616     std::string title,
1617     std::string yaxis_label,
1618     Plot* plot) {
1619   std::map<uint32_t, TimeSeries> sr_reports_by_ssrc;
1620   const auto& sender_reports = parsed_log_.sender_reports(direction);
1621   for (const auto& rtcp : sender_reports) {
1622     float x = config_.GetCallTimeSec(rtcp.log_time());
1623     uint32_t ssrc = rtcp.sr.sender_ssrc();
1624     for (const auto& block : rtcp.sr.report_blocks()) {
1625       float y = fy(block);
1626       auto sr_report_it = sr_reports_by_ssrc.find(ssrc);
1627       bool inserted;
1628       if (sr_report_it == sr_reports_by_ssrc.end()) {
1629         std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace(
1630             ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) +
1631                                  " Sender Reports",
1632                              LineStyle::kLine, PointStyle::kHighlight));
1633       }
1634       sr_report_it->second.points.emplace_back(x, y);
1635     }
1636   }
1637   for (auto& kv : sr_reports_by_ssrc) {
1638     plot->AppendTimeSeries(std::move(kv.second));
1639   }
1640 
1641   std::map<uint32_t, TimeSeries> rr_reports_by_ssrc;
1642   const auto& receiver_reports = parsed_log_.receiver_reports(direction);
1643   for (const auto& rtcp : receiver_reports) {
1644     float x = config_.GetCallTimeSec(rtcp.log_time());
1645     uint32_t ssrc = rtcp.rr.sender_ssrc();
1646     for (const auto& block : rtcp.rr.report_blocks()) {
1647       float y = fy(block);
1648       auto rr_report_it = rr_reports_by_ssrc.find(ssrc);
1649       bool inserted;
1650       if (rr_report_it == rr_reports_by_ssrc.end()) {
1651         std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace(
1652             ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) +
1653                                  " Receiver Reports",
1654                              LineStyle::kLine, PointStyle::kHighlight));
1655       }
1656       rr_report_it->second.points.emplace_back(x, y);
1657     }
1658   }
1659   for (auto& kv : rr_reports_by_ssrc) {
1660     plot->AppendTimeSeries(std::move(kv.second));
1661   }
1662 
1663   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1664                  "Time (s)", kLeftMargin, kRightMargin);
1665   plot->SetSuggestedYAxis(0, 1, yaxis_label, kBottomMargin, kTopMargin);
1666   plot->SetTitle(title);
1667 }
1668 
CreateIceCandidatePairConfigGraph(Plot * plot)1669 void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
1670   std::map<uint32_t, TimeSeries> configs_by_cp_id;
1671   for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
1672     if (configs_by_cp_id.find(config.candidate_pair_id) ==
1673         configs_by_cp_id.end()) {
1674       const std::string candidate_pair_desc =
1675           GetCandidatePairLogDescriptionAsString(config);
1676       configs_by_cp_id[config.candidate_pair_id] =
1677           TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
1678                          candidate_pair_desc,
1679                      LineStyle::kNone, PointStyle::kHighlight);
1680       candidate_pair_desc_by_id_[config.candidate_pair_id] =
1681           candidate_pair_desc;
1682     }
1683     float x = config_.GetCallTimeSec(config.log_time());
1684     float y = static_cast<float>(config.type);
1685     configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
1686   }
1687 
1688   // TODO(qingsi): There can be a large number of candidate pairs generated by
1689   // certain calls and the frontend cannot render the chart in this case due to
1690   // the failure of generating a palette with the same number of colors.
1691   for (auto& kv : configs_by_cp_id) {
1692     plot->AppendTimeSeries(std::move(kv.second));
1693   }
1694 
1695   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1696                  "Time (s)", kLeftMargin, kRightMargin);
1697   plot->SetSuggestedYAxis(0, 3, "Config Type", kBottomMargin, kTopMargin);
1698   plot->SetTitle("[IceEventLog] ICE candidate pair configs");
1699   plot->SetYAxisTickLabels(
1700       {{static_cast<float>(IceCandidatePairConfigType::kAdded), "ADDED"},
1701        {static_cast<float>(IceCandidatePairConfigType::kUpdated), "UPDATED"},
1702        {static_cast<float>(IceCandidatePairConfigType::kDestroyed),
1703         "DESTROYED"},
1704        {static_cast<float>(IceCandidatePairConfigType::kSelected),
1705         "SELECTED"}});
1706 }
1707 
GetCandidatePairLogDescriptionFromId(uint32_t candidate_pair_id)1708 std::string EventLogAnalyzer::GetCandidatePairLogDescriptionFromId(
1709     uint32_t candidate_pair_id) {
1710   if (candidate_pair_desc_by_id_.find(candidate_pair_id) !=
1711       candidate_pair_desc_by_id_.end()) {
1712     return candidate_pair_desc_by_id_[candidate_pair_id];
1713   }
1714   for (const auto& config : parsed_log_.ice_candidate_pair_configs()) {
1715     // TODO(qingsi): Add the handling of the "Updated" config event after the
1716     // visualization of property change for candidate pairs is introduced.
1717     if (candidate_pair_desc_by_id_.find(config.candidate_pair_id) ==
1718         candidate_pair_desc_by_id_.end()) {
1719       const std::string candidate_pair_desc =
1720           GetCandidatePairLogDescriptionAsString(config);
1721       candidate_pair_desc_by_id_[config.candidate_pair_id] =
1722           candidate_pair_desc;
1723     }
1724   }
1725   return candidate_pair_desc_by_id_[candidate_pair_id];
1726 }
1727 
CreateIceConnectivityCheckGraph(Plot * plot)1728 void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
1729   constexpr int kEventTypeOffset =
1730       static_cast<int>(IceCandidatePairConfigType::kNumValues);
1731   std::map<uint32_t, TimeSeries> checks_by_cp_id;
1732   for (const auto& event : parsed_log_.ice_candidate_pair_events()) {
1733     if (checks_by_cp_id.find(event.candidate_pair_id) ==
1734         checks_by_cp_id.end()) {
1735       checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
1736           "[" + std::to_string(event.candidate_pair_id) + "]" +
1737               GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
1738           LineStyle::kNone, PointStyle::kHighlight);
1739     }
1740     float x = config_.GetCallTimeSec(event.log_time());
1741     float y = static_cast<float>(event.type) + kEventTypeOffset;
1742     checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
1743   }
1744 
1745   // TODO(qingsi): The same issue as in CreateIceCandidatePairConfigGraph.
1746   for (auto& kv : checks_by_cp_id) {
1747     plot->AppendTimeSeries(std::move(kv.second));
1748   }
1749 
1750   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1751                  "Time (s)", kLeftMargin, kRightMargin);
1752   plot->SetSuggestedYAxis(0, 4, "Connectivity State", kBottomMargin,
1753                           kTopMargin);
1754   plot->SetTitle("[IceEventLog] ICE connectivity checks");
1755 
1756   plot->SetYAxisTickLabels(
1757       {{static_cast<float>(IceCandidatePairEventType::kCheckSent) +
1758             kEventTypeOffset,
1759         "CHECK SENT"},
1760        {static_cast<float>(IceCandidatePairEventType::kCheckReceived) +
1761             kEventTypeOffset,
1762         "CHECK RECEIVED"},
1763        {static_cast<float>(IceCandidatePairEventType::kCheckResponseSent) +
1764             kEventTypeOffset,
1765         "RESPONSE SENT"},
1766        {static_cast<float>(IceCandidatePairEventType::kCheckResponseReceived) +
1767             kEventTypeOffset,
1768         "RESPONSE RECEIVED"}});
1769 }
1770 
CreateDtlsTransportStateGraph(Plot * plot)1771 void EventLogAnalyzer::CreateDtlsTransportStateGraph(Plot* plot) {
1772   TimeSeries states("DTLS Transport State", LineStyle::kNone,
1773                     PointStyle::kHighlight);
1774   for (const auto& event : parsed_log_.dtls_transport_states()) {
1775     float x = config_.GetCallTimeSec(event.log_time());
1776     float y = static_cast<float>(event.dtls_transport_state);
1777     states.points.emplace_back(x, y);
1778   }
1779   plot->AppendTimeSeries(std::move(states));
1780   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1781                  "Time (s)", kLeftMargin, kRightMargin);
1782   plot->SetSuggestedYAxis(0, static_cast<float>(DtlsTransportState::kNumValues),
1783                           "Transport State", kBottomMargin, kTopMargin);
1784   plot->SetTitle("DTLS Transport State");
1785   plot->SetYAxisTickLabels(
1786       {{static_cast<float>(DtlsTransportState::kNew), "NEW"},
1787        {static_cast<float>(DtlsTransportState::kConnecting), "CONNECTING"},
1788        {static_cast<float>(DtlsTransportState::kConnected), "CONNECTED"},
1789        {static_cast<float>(DtlsTransportState::kClosed), "CLOSED"},
1790        {static_cast<float>(DtlsTransportState::kFailed), "FAILED"}});
1791 }
1792 
CreateDtlsWritableStateGraph(Plot * plot)1793 void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) {
1794   TimeSeries writable("DTLS Writable", LineStyle::kNone,
1795                       PointStyle::kHighlight);
1796   for (const auto& event : parsed_log_.dtls_writable_states()) {
1797     float x = config_.GetCallTimeSec(event.log_time());
1798     float y = static_cast<float>(event.writable);
1799     writable.points.emplace_back(x, y);
1800   }
1801   plot->AppendTimeSeries(std::move(writable));
1802   plot->SetXAxis(config_.CallBeginTimeSec(), config_.CallEndTimeSec(),
1803                  "Time (s)", kLeftMargin, kRightMargin);
1804   plot->SetSuggestedYAxis(0, 1, "Writable", kBottomMargin, kTopMargin);
1805   plot->SetTitle("DTLS Writable State");
1806 }
1807 
1808 }  // namespace webrtc
1809