diff options
author | Bjorn Terelius <terelius@webrtc.org> | 2020-05-19 10:57:24 +0200 |
---|---|---|
committer | Commit Bot <commit-bot@chromium.org> | 2020-05-19 09:45:16 +0000 |
commit | 48b82798132248dfa1aaf0ed3dcac57a44a6855f (patch) | |
tree | 9d9d31afc7b31fe77ea00695ce6a005986bba71c /rtc_tools | |
parent | 41559a2b46a80fb642b36bed6fa6bc1a43ce1238 (diff) | |
download | webrtc-48b82798132248dfa1aaf0ed3dcac57a44a6855f.tar.gz |
Refactor/reimplement RTC event log triage alerts.
- Moves AnalyzerConfig and helper functions IsAudioSsrc, IsVideoSsrc, IsRtxSsrc, GetStreamNam and GetLayerName to analyzer_common.h
- Moves log_segments() code to rtc_event_log_parser.h
- Moves TriageAlert/Notification code to a new file with a couple of minor fixes to make it less spammy.
Bug: webrtc:11566
Change-Id: Ib33941d8185f7382fc72ed65768e46015e0320de
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/174824
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Reviewed-by: Mirko Bonadei <mbonadei@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31318}
Diffstat (limited to 'rtc_tools')
-rw-r--r-- | rtc_tools/BUILD.gn | 5 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/alerts.cc | 228 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/alerts.h | 86 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/analyzer.cc | 299 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/analyzer.h | 166 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/analyzer_common.cc | 83 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/analyzer_common.h | 79 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/main.cc | 28 | ||||
-rw-r--r-- | rtc_tools/rtc_event_log_visualizer/triage_notifications.h | 158 |
9 files changed, 562 insertions, 570 deletions
diff --git a/rtc_tools/BUILD.gn b/rtc_tools/BUILD.gn index f293853f6e..3d398455bd 100644 --- a/rtc_tools/BUILD.gn +++ b/rtc_tools/BUILD.gn @@ -319,8 +319,12 @@ if (!build_with_chromium) { rtc_library("event_log_visualizer_utils") { visibility = [ "*" ] sources = [ + "rtc_event_log_visualizer/alerts.cc", + "rtc_event_log_visualizer/alerts.h", "rtc_event_log_visualizer/analyzer.cc", "rtc_event_log_visualizer/analyzer.h", + "rtc_event_log_visualizer/analyzer_common.cc", + "rtc_event_log_visualizer/analyzer_common.h", "rtc_event_log_visualizer/log_simulation.cc", "rtc_event_log_visualizer/log_simulation.h", "rtc_event_log_visualizer/plot_base.cc", @@ -329,7 +333,6 @@ if (!build_with_chromium) { "rtc_event_log_visualizer/plot_protobuf.h", "rtc_event_log_visualizer/plot_python.cc", "rtc_event_log_visualizer/plot_python.h", - "rtc_event_log_visualizer/triage_notifications.h", ] deps = [ ":chart_proto", diff --git a/rtc_tools/rtc_event_log_visualizer/alerts.cc b/rtc_tools/rtc_event_log_visualizer/alerts.cc new file mode 100644 index 0000000000..da059cb5a2 --- /dev/null +++ b/rtc_tools/rtc_event_log_visualizer/alerts.cc @@ -0,0 +1,228 @@ +/* + * Copyright (c) 2020 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#include "rtc_tools/rtc_event_log_visualizer/alerts.h" + +#include <stdio.h> + +#include <algorithm> +#include <limits> +#include <map> +#include <string> + +#include "logging/rtc_event_log/rtc_event_processor.h" +#include "rtc_base/checks.h" +#include "rtc_base/format_macros.h" +#include "rtc_base/logging.h" +#include "rtc_base/numerics/sequence_number_util.h" +#include "rtc_base/strings/string_builder.h" + +namespace webrtc { + +void TriageHelper::Print(FILE* file) { + fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n"); + for (const auto& alert : triage_alerts_) { + fprintf(file, "%d %s. First occurence at %3.3lf\n", alert.second.count, + alert.second.explanation.c_str(), alert.second.first_occurence); + } + fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n"); +} + +void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log, + PacketDirection direction) { + // With 100 packets/s (~800kbps), false positives would require 10 s without + // data. + constexpr int64_t kMaxSeqNumJump = 1000; + // With a 90 kHz clock, false positives would require 10 s without data. + constexpr int64_t kMaxCaptureTimeJump = 900000; + + std::string seq_num_explanation = + direction == kIncomingPacket + ? "Incoming RTP sequence number jumps more than 1000. Counter may " + "have been reset or rewritten incorrectly in a group call." + : "Outgoing RTP sequence number jumps more than 1000. Counter may " + "have been reset."; + std::string capture_time_explanation = + direction == kIncomingPacket ? "Incoming capture time jumps more than " + "10s. Clock might have been reset." + : "Outgoing capture time jumps more than " + "10s. Clock might have been reset."; + TriageAlertType seq_num_alert = direction == kIncomingPacket + ? TriageAlertType::kIncomingSeqNumJump + : TriageAlertType::kOutgoingSeqNumJump; + TriageAlertType capture_time_alert = + direction == kIncomingPacket ? TriageAlertType::kIncomingCaptureTimeJump + : TriageAlertType::kOutgoingCaptureTimeJump; + + const int64_t segment_end_us = + parsed_log.log_segments().empty() + ? std::numeric_limits<int64_t>::max() + : parsed_log.log_segments().front().stop_time_us(); + + // Check for gaps in sequence numbers and capture timestamps. + for (const auto& stream : parsed_log.rtp_packets_by_ssrc(direction)) { + if (IsRtxSsrc(parsed_log, direction, stream.ssrc)) { + continue; + } + SeqNumUnwrapper<uint16_t> seq_num_unwrapper; + absl::optional<int64_t> last_seq_num; + SeqNumUnwrapper<uint32_t> capture_time_unwrapper; + absl::optional<int64_t> last_capture_time; + for (const auto& packet : stream.packet_view) { + if (packet.log_time_us() > segment_end_us) { + // Only process the first (LOG_START, LOG_END) segment. + break; + } + + int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber); + if (last_seq_num.has_value() && + std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) { + Alert(seq_num_alert, config_.GetCallTimeSec(packet.log_time_us()), + seq_num_explanation); + } + last_seq_num.emplace(seq_num); + + int64_t capture_time = + capture_time_unwrapper.Unwrap(packet.header.timestamp); + if (last_capture_time.has_value() && + std::abs(capture_time - last_capture_time.value()) > + kMaxCaptureTimeJump) { + Alert(capture_time_alert, config_.GetCallTimeSec(packet.log_time_us()), + capture_time_explanation); + } + last_capture_time.emplace(capture_time); + } + } +} + +void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log, + PacketDirection direction) { + constexpr int64_t kMaxRtpTransmissionGap = 500000; + constexpr int64_t kMaxRtcpTransmissionGap = 2000000; + std::string rtp_explanation = + direction == kIncomingPacket + ? "No RTP packets received for more than 500ms. This indicates a " + "network problem. Temporary video freezes and choppy or robotic " + "audio is unavoidable. Unnecessary BWE drops is a known issue." + : "No RTP packets sent for more than 500 ms. This might be an issue " + "with the pacer."; + std::string rtcp_explanation = + direction == kIncomingPacket + ? "No RTCP packets received for more than 2 s. Could be a longer " + "connection outage" + : "No RTCP sent for more than 2 s. This is most likely a bug."; + TriageAlertType rtp_alert = direction == kIncomingPacket + ? TriageAlertType::kIncomingRtpGap + : TriageAlertType::kOutgoingRtpGap; + TriageAlertType rtcp_alert = direction == kIncomingPacket + ? TriageAlertType::kIncomingRtcpGap + : TriageAlertType::kOutgoingRtcpGap; + + const int64_t segment_end_us = + parsed_log.log_segments().empty() + ? std::numeric_limits<int64_t>::max() + : parsed_log.log_segments().front().stop_time_us(); + + // TODO(terelius): The parser could provide a list of all packets, ordered + // by time, for each direction. + std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction; + for (const auto& stream : parsed_log.rtp_packets_by_ssrc(direction)) { + for (const LoggedRtpPacket& rtp_packet : stream.packet_view) + rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet); + } + absl::optional<int64_t> last_rtp_time; + for (const auto& kv : rtp_in_direction) { + int64_t timestamp = kv.first; + if (timestamp > segment_end_us) { + // Only process the first (LOG_START, LOG_END) segment. + break; + } + int64_t duration = timestamp - last_rtp_time.value_or(0); + if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) { + // No packet sent/received for more than 500 ms. + Alert(rtp_alert, config_.GetCallTimeSec(timestamp), rtp_explanation); + } + last_rtp_time.emplace(timestamp); + } + + absl::optional<int64_t> last_rtcp_time; + if (direction == kIncomingPacket) { + for (const auto& rtcp : parsed_log.incoming_rtcp_packets()) { + if (rtcp.log_time_us() > segment_end_us) { + // Only process the first (LOG_START, LOG_END) segment. + break; + } + int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0); + if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) { + // No feedback sent/received for more than 2000 ms. + Alert(rtcp_alert, config_.GetCallTimeSec(rtcp.log_time_us()), + rtcp_explanation); + } + last_rtcp_time.emplace(rtcp.log_time_us()); + } + } else { + for (const auto& rtcp : parsed_log.outgoing_rtcp_packets()) { + if (rtcp.log_time_us() > segment_end_us) { + // Only process the first (LOG_START, LOG_END) segment. + break; + } + int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0); + if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) { + // No feedback sent/received for more than 2000 ms. + Alert(rtcp_alert, config_.GetCallTimeSec(rtcp.log_time_us()), + rtcp_explanation); + } + last_rtcp_time.emplace(rtcp.log_time_us()); + } + } +} + +// TODO(terelius): Notifications could possibly be generated by the same code +// that produces the graphs. There is some code duplication that could be +// avoided, but that might be solved anyway when we move functionality from the +// analyzer to the parser. +void TriageHelper::AnalyzeLog(const ParsedRtcEventLog& parsed_log) { + AnalyzeStreamGaps(parsed_log, kIncomingPacket); + AnalyzeStreamGaps(parsed_log, kOutgoingPacket); + AnalyzeTransmissionGaps(parsed_log, kIncomingPacket); + AnalyzeTransmissionGaps(parsed_log, kOutgoingPacket); + + const int64_t segment_end_us = + parsed_log.log_segments().empty() + ? std::numeric_limits<int64_t>::max() + : parsed_log.log_segments().front().stop_time_us(); + + int64_t first_occurence = parsed_log.last_timestamp(); + constexpr double kMaxLossFraction = 0.05; + // Loss feedback + int64_t total_lost_packets = 0; + int64_t total_expected_packets = 0; + for (auto& bwe_update : parsed_log.bwe_loss_updates()) { + if (bwe_update.log_time_us() > segment_end_us) { + // Only process the first (LOG_START, LOG_END) segment. + break; + } + int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 * + bwe_update.expected_packets; + total_lost_packets += lost_packets; + total_expected_packets += bwe_update.expected_packets; + if (bwe_update.fraction_lost >= 255 * kMaxLossFraction) { + first_occurence = std::min(first_occurence, bwe_update.log_time_us()); + } + } + double avg_outgoing_loss = + static_cast<double>(total_lost_packets) / total_expected_packets; + if (avg_outgoing_loss > kMaxLossFraction) { + Alert(TriageAlertType::kOutgoingHighLoss, first_occurence, + "More than 5% of outgoing packets lost."); + } +} + +} // namespace webrtc diff --git a/rtc_tools/rtc_event_log_visualizer/alerts.h b/rtc_tools/rtc_event_log_visualizer/alerts.h new file mode 100644 index 0000000000..9e559e6af4 --- /dev/null +++ b/rtc_tools/rtc_event_log_visualizer/alerts.h @@ -0,0 +1,86 @@ +/* + * Copyright (c) 2020 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#ifndef RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_ALERTS_H_ +#define RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_ALERTS_H_ + +#include <stdio.h> + +#include <map> +#include <string> +#include <utility> + +#include "absl/strings/string_view.h" +#include "logging/rtc_event_log/rtc_event_log_parser.h" +#include "rtc_base/constructor_magic.h" +#include "rtc_tools/rtc_event_log_visualizer/analyzer_common.h" + +namespace webrtc { + +enum class TriageAlertType { + kUnknown = 0, + kIncomingRtpGap, + kOutgoingRtpGap, + kIncomingRtcpGap, + kOutgoingRtcpGap, + kIncomingSeqNumJump, + kOutgoingSeqNumJump, + kIncomingCaptureTimeJump, + kOutgoingCaptureTimeJump, + kOutgoingHighLoss, + kLast, +}; + +struct TriageAlert { + TriageAlertType type = TriageAlertType::kUnknown; + int count = 0; + float first_occurence = -1; + std::string explanation; +}; + +class TriageHelper { + public: + explicit TriageHelper(const AnalyzerConfig& config) : config_(config) {} + + void AnalyzeLog(const ParsedRtcEventLog& parsed_log); + + void AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log, + PacketDirection direction); + void AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log, + PacketDirection direction); + void Print(FILE* file); + + private: + AnalyzerConfig config_; + std::map<TriageAlertType, TriageAlert> triage_alerts_; + + void Alert(TriageAlertType type, + float time_seconds, + absl::string_view explanation) { + std::map<TriageAlertType, TriageAlert>::iterator it = + triage_alerts_.find(type); + + if (it == triage_alerts_.end()) { + TriageAlert alert; + alert.type = type; + alert.first_occurence = time_seconds; + alert.count = 1; + alert.explanation = std::string(explanation); + triage_alerts_.insert(std::make_pair(type, alert)); + } else { + it->second.count += 1; + } + } + RTC_DISALLOW_COPY_AND_ASSIGN(TriageHelper); +}; + +} // namespace webrtc + +#endif // RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_ALERTS_H_ diff --git a/rtc_tools/rtc_event_log_visualizer/analyzer.cc b/rtc_tools/rtc_event_log_visualizer/analyzer.cc index 9fcb510adc..9a9a4553f8 100644 --- a/rtc_tools/rtc_event_log_visualizer/analyzer.cc +++ b/rtc_tools/rtc_event_log_visualizer/analyzer.cc @@ -465,31 +465,14 @@ EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log, config_.begin_time_ = config_.end_time_ = 0; } - const auto& log_start_events = parsed_log_.start_log_events(); - const auto& log_end_events = parsed_log_.stop_log_events(); - auto start_iter = log_start_events.begin(); - auto end_iter = log_end_events.begin(); - while (start_iter != log_start_events.end()) { - int64_t start = start_iter->log_time_us(); - ++start_iter; - absl::optional<int64_t> next_start; - if (start_iter != log_start_events.end()) - next_start.emplace(start_iter->log_time_us()); - if (end_iter != log_end_events.end() && - end_iter->log_time_us() <= - next_start.value_or(std::numeric_limits<int64_t>::max())) { - int64_t end = end_iter->log_time_us(); - RTC_DCHECK_LE(start, end); - log_segments_.push_back(std::make_pair(start, end)); - ++end_iter; - } else { - // we're missing an end event. Assume that it occurred just before the - // next start. - log_segments_.push_back( - std::make_pair(start, next_start.value_or(config_.end_time_))); - } - } - RTC_LOG(LS_INFO) << "Found " << log_segments_.size() + RTC_LOG(LS_INFO) << "Found " << parsed_log_.log_segments().size() + << " (LOG_START, LOG_END) segments in log."; +} + +EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log, + const AnalyzerConfig& config) + : parsed_log_(log), config_(config) { + RTC_LOG(LS_INFO) << "Found " << parsed_log_.log_segments().size() << " (LOG_START, LOG_END) segments in log."; } @@ -527,7 +510,7 @@ void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction, continue; } - TimeSeries time_series(GetStreamName(direction, stream.ssrc), + TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc), LineStyle::kBar); auto GetPacketSize = [](const LoggedRtpPacket& packet) { return absl::optional<float>(packet.total_length); @@ -597,8 +580,8 @@ void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction, for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) { if (!MatchingSsrc(stream.ssrc, desired_ssrc_)) continue; - std::string label = - std::string("RTP ") + GetStreamName(direction, stream.ssrc); + std::string label = std::string("RTP ") + + GetStreamName(parsed_log_, direction, stream.ssrc); CreateAccumulatedPacketsTimeSeries(plot, stream.packet_view, label); } std::string label = @@ -627,7 +610,8 @@ void EventLogAnalyzer::CreatePacketRateGraph(PacketDirection direction, continue; } TimeSeries time_series( - std::string("RTP ") + GetStreamName(direction, stream.ssrc), + std::string("RTP ") + + GetStreamName(parsed_log_, direction, stream.ssrc), LineStyle::kLine); MovingAverage<LoggedRtpPacket, double>(CountPackets, stream.packet_view, config_, &time_series); @@ -736,9 +720,9 @@ void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) { void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction, Plot* plot) { for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) { - if (!IsAudioSsrc(direction, stream.ssrc)) + if (!IsAudioSsrc(parsed_log_, direction, stream.ssrc)) continue; - TimeSeries time_series(GetStreamName(direction, stream.ssrc), + TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc), LineStyle::kLine); for (auto& packet : stream.packet_view) { if (packet.header.extension.hasAudioLevel) { @@ -767,8 +751,9 @@ void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) { continue; } - TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc), - LineStyle::kBar); + TimeSeries time_series( + GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc), + LineStyle::kBar); auto GetSequenceNumberDiff = [](const LoggedRtpPacketIncoming& old_packet, const LoggedRtpPacketIncoming& new_packet) { int64_t diff = @@ -801,8 +786,9 @@ void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) { continue; } - TimeSeries time_series(GetStreamName(kIncomingPacket, stream.ssrc), - LineStyle::kLine, PointStyle::kHighlight); + TimeSeries time_series( + GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc), + LineStyle::kLine, PointStyle::kHighlight); // TODO(terelius): Should the window and step size be read from the class // instead? const int64_t kWindowUs = 1000000; @@ -855,7 +841,7 @@ void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) { for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) { // Filter on SSRC. if (!MatchingSsrc(stream.ssrc, desired_ssrc_) || - IsRtxSsrc(kIncomingPacket, stream.ssrc)) { + IsRtxSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) { continue; } @@ -866,15 +852,17 @@ void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) { << packets.size() << " packets in the stream."; continue; } - int64_t end_time_us = log_segments_.empty() - ? std::numeric_limits<int64_t>::max() - : log_segments_.front().second; + int64_t segment_end_us = + parsed_log_.log_segments().empty() + ? std::numeric_limits<int64_t>::max() + : parsed_log_.log_segments().front().stop_time_us(); absl::optional<uint32_t> estimated_frequency = - EstimateRtpClockFrequency(packets, end_time_us); + EstimateRtpClockFrequency(packets, segment_end_us); if (!estimated_frequency) continue; const double frequency_hz = *estimated_frequency; - if (IsVideoSsrc(kIncomingPacket, stream.ssrc) && frequency_hz != 90000) { + if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc) && + frequency_hz != 90000) { RTC_LOG(LS_WARNING) << "Video stream should use a 90 kHz clock but appears to use " << frequency_hz / 1000 << ". Discarding."; @@ -891,14 +879,16 @@ void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) { }; TimeSeries capture_time_data( - GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time", + GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) + + " capture-time", LineStyle::kLine); AccumulatePairs<LoggedRtpPacketIncoming, double>( ToCallTime, ToNetworkDelay, packets, &capture_time_data); plot->AppendTimeSeries(std::move(capture_time_data)); TimeSeries send_time_data( - GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time", + GetStreamName(parsed_log_, kIncomingPacket, stream.ssrc) + + " abs-send-time", LineStyle::kLine); AccumulatePairs<LoggedRtpPacketIncoming, double>( ToCallTime, NetworkDelayDiff_AbsSendTime, packets, &send_time_data); @@ -1191,7 +1181,7 @@ void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction, continue; } - TimeSeries time_series(GetStreamName(direction, stream.ssrc), + TimeSeries time_series(GetStreamName(parsed_log_, direction, stream.ssrc), LineStyle::kLine); auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) { return packet.total_length * 8.0 / 1000.0; @@ -1483,7 +1473,7 @@ void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) { std::multimap<int64_t, const RtpPacketType*> incoming_rtp; for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) { - if (IsVideoSsrc(kIncomingPacket, stream.ssrc)) { + if (IsVideoSsrc(parsed_log_, kIncomingPacket, stream.ssrc)) { for (const auto& rtp_packet : stream.incoming_packets) incoming_rtp.insert( std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet)); @@ -1586,7 +1576,7 @@ void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) { const std::vector<LoggedRtpPacketOutgoing>& packets = stream.outgoing_packets; - if (IsRtxSsrc(kOutgoingPacket, stream.ssrc)) { + if (IsRtxSsrc(parsed_log_, kOutgoingPacket, stream.ssrc)) { continue; } @@ -1596,14 +1586,15 @@ void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) { "pacer delay with less than 2 packets in the stream"; continue; } - int64_t end_time_us = log_segments_.empty() - ? std::numeric_limits<int64_t>::max() - : log_segments_.front().second; + int64_t segment_end_us = + parsed_log_.log_segments().empty() + ? std::numeric_limits<int64_t>::max() + : parsed_log_.log_segments().front().stop_time_us(); absl::optional<uint32_t> estimated_frequency = - EstimateRtpClockFrequency(packets, end_time_us); + EstimateRtpClockFrequency(packets, segment_end_us); if (!estimated_frequency) continue; - if (IsVideoSsrc(kOutgoingPacket, stream.ssrc) && + if (IsVideoSsrc(parsed_log_, kOutgoingPacket, stream.ssrc) && *estimated_frequency != 90000) { RTC_LOG(LS_WARNING) << "Video stream should use a 90 kHz clock but appears to use " @@ -1612,7 +1603,7 @@ void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) { } TimeSeries pacer_delay_series( - GetStreamName(kOutgoingPacket, stream.ssrc) + "(" + + GetStreamName(parsed_log_, kOutgoingPacket, stream.ssrc) + "(" + std::to_string(*estimated_frequency / 1000) + " kHz)", LineStyle::kLine, PointStyle::kHighlight); SeqNumUnwrapper<uint32_t> timestamp_unwrapper; @@ -1645,7 +1636,7 @@ void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction, Plot* plot) { for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) { TimeSeries rtp_timestamps( - GetStreamName(direction, stream.ssrc) + " capture-time", + GetStreamName(parsed_log_, direction, stream.ssrc) + " capture-time", LineStyle::kLine, PointStyle::kHighlight); for (const auto& packet : stream.packet_view) { float x = config_.GetCallTimeSec(packet.log_time_us()); @@ -1655,7 +1646,8 @@ void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction, plot->AppendTimeSeries(std::move(rtp_timestamps)); TimeSeries rtcp_timestamps( - GetStreamName(direction, stream.ssrc) + " rtcp capture-time", + GetStreamName(parsed_log_, direction, stream.ssrc) + + " rtcp capture-time", LineStyle::kLine, PointStyle::kHighlight); // TODO(terelius): Why only sender reports? const auto& sender_reports = parsed_log_.sender_reports(direction); @@ -1692,7 +1684,8 @@ void EventLogAnalyzer::CreateSenderAndReceiverReportPlot( bool inserted; if (sr_report_it == sr_reports_by_ssrc.end()) { std::tie(sr_report_it, inserted) = sr_reports_by_ssrc.emplace( - ssrc, TimeSeries(GetStreamName(direction, ssrc) + " Sender Reports", + ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) + + " Sender Reports", LineStyle::kLine, PointStyle::kHighlight)); } sr_report_it->second.points.emplace_back(x, y); @@ -1713,9 +1706,9 @@ void EventLogAnalyzer::CreateSenderAndReceiverReportPlot( bool inserted; if (rr_report_it == rr_reports_by_ssrc.end()) { std::tie(rr_report_it, inserted) = rr_reports_by_ssrc.emplace( - ssrc, - TimeSeries(GetStreamName(direction, ssrc) + " Receiver Reports", - LineStyle::kLine, PointStyle::kHighlight)); + ssrc, TimeSeries(GetStreamName(parsed_log_, direction, ssrc) + + " Receiver Reports", + LineStyle::kLine, PointStyle::kHighlight)); } rr_report_it->second.points.emplace_back(x, y); } @@ -2038,7 +2031,7 @@ EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq( for (const auto& stream : parsed_log_.incoming_rtp_packets_by_ssrc()) { const uint32_t ssrc = stream.ssrc; - if (!IsAudioSsrc(kIncomingPacket, ssrc)) + if (!IsAudioSsrc(parsed_log_, kIncomingPacket, ssrc)) continue; const std::vector<LoggedRtpPacketIncoming>* audio_packets = &stream.incoming_packets; @@ -2058,9 +2051,10 @@ EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq( } absl::optional<int64_t> end_time_ms = - log_segments_.empty() + parsed_log_.log_segments().empty() ? absl::nullopt - : absl::optional<int64_t>(log_segments_.front().second / 1000); + : absl::optional<int64_t>( + parsed_log_.log_segments().front().stop_time_ms()); neteq_stats[ssrc] = CreateNetEqTestAndRun( audio_packets, &output_events_it->second, end_time_ms, @@ -2124,7 +2118,8 @@ void EventLogAnalyzer::CreateAudioJitterBufferGraph( "Time (s)", kLeftMargin, kRightMargin); plot->SetSuggestedYAxis(0, 1, "Relative delay (ms)", kBottomMargin, kTopMargin); - plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc)); + plot->SetTitle("NetEq timing for " + + GetStreamName(parsed_log_, kIncomingPacket, ssrc)); } template <typename NetEqStatsType> @@ -2150,7 +2145,8 @@ void EventLogAnalyzer::CreateNetEqStatsGraphInternal( } for (auto& series : time_series) { - series.second.label = GetStreamName(kIncomingPacket, series.first); + series.second.label = + GetStreamName(parsed_log_, kIncomingPacket, series.first); series.second.line_style = LineStyle::kLine; plot->AppendTimeSeries(std::move(series.second)); } @@ -2326,181 +2322,4 @@ void EventLogAnalyzer::CreateDtlsWritableStateGraph(Plot* plot) { plot->SetTitle("DTLS Writable State"); } -void EventLogAnalyzer::PrintNotifications(FILE* file) { - fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n"); - for (const auto& alert : incoming_rtp_recv_time_gaps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : incoming_rtcp_recv_time_gaps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : outgoing_rtp_send_time_gaps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : outgoing_rtcp_send_time_gaps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : incoming_seq_num_jumps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : incoming_capture_time_jumps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : outgoing_seq_num_jumps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : outgoing_capture_time_jumps_) { - fprintf(file, "%3.3lf s : %s\n", alert.Time(), alert.ToString().c_str()); - } - for (const auto& alert : outgoing_high_loss_alerts_) { - fprintf(file, " : %s\n", alert.ToString().c_str()); - } - fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n"); -} - -void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) { - // With 100 packets/s (~800kbps), false positives would require 10 s without - // data. - constexpr int64_t kMaxSeqNumJump = 1000; - // With a 90 kHz clock, false positives would require 10 s without data. - constexpr int64_t kMaxCaptureTimeJump = 900000; - - int64_t end_time_us = log_segments_.empty() - ? std::numeric_limits<int64_t>::max() - : log_segments_.front().second; - - SeqNumUnwrapper<uint16_t> seq_num_unwrapper; - absl::optional<int64_t> last_seq_num; - SeqNumUnwrapper<uint32_t> capture_time_unwrapper; - absl::optional<int64_t> last_capture_time; - // Check for gaps in sequence numbers and capture timestamps. - for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) { - for (const auto& packet : stream.packet_view) { - if (packet.log_time_us() > end_time_us) { - // Only process the first (LOG_START, LOG_END) segment. - break; - } - - int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber); - if (last_seq_num.has_value() && - std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) { - Alert_SeqNumJump(direction, - config_.GetCallTimeSec(packet.log_time_us()), - packet.header.ssrc); - } - last_seq_num.emplace(seq_num); - - int64_t capture_time = - capture_time_unwrapper.Unwrap(packet.header.timestamp); - if (last_capture_time.has_value() && - std::abs(capture_time - last_capture_time.value()) > - kMaxCaptureTimeJump) { - Alert_CaptureTimeJump(direction, - config_.GetCallTimeSec(packet.log_time_us()), - packet.header.ssrc); - } - last_capture_time.emplace(capture_time); - } - } -} - -void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) { - constexpr int64_t kMaxRtpTransmissionGap = 500000; - constexpr int64_t kMaxRtcpTransmissionGap = 2000000; - int64_t end_time_us = log_segments_.empty() - ? std::numeric_limits<int64_t>::max() - : log_segments_.front().second; - - // TODO(terelius): The parser could provide a list of all packets, ordered - // by time, for each direction. - std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction; - for (const auto& stream : parsed_log_.rtp_packets_by_ssrc(direction)) { - for (const LoggedRtpPacket& rtp_packet : stream.packet_view) - rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet); - } - absl::optional<int64_t> last_rtp_time; - for (const auto& kv : rtp_in_direction) { - int64_t timestamp = kv.first; - if (timestamp > end_time_us) { - // Only process the first (LOG_START, LOG_END) segment. - break; - } - int64_t duration = timestamp - last_rtp_time.value_or(0); - if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) { - // No packet sent/received for more than 500 ms. - Alert_RtpLogTimeGap(direction, config_.GetCallTimeSec(timestamp), - duration / 1000); - } - last_rtp_time.emplace(timestamp); - } - - absl::optional<int64_t> last_rtcp_time; - if (direction == kIncomingPacket) { - for (const auto& rtcp : parsed_log_.incoming_rtcp_packets()) { - if (rtcp.log_time_us() > end_time_us) { - // Only process the first (LOG_START, LOG_END) segment. - break; - } - int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0); - if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) { - // No feedback sent/received for more than 2000 ms. - Alert_RtcpLogTimeGap(direction, - config_.GetCallTimeSec(rtcp.log_time_us()), - duration / 1000); - } - last_rtcp_time.emplace(rtcp.log_time_us()); - } - } else { - for (const auto& rtcp : parsed_log_.outgoing_rtcp_packets()) { - if (rtcp.log_time_us() > end_time_us) { - // Only process the first (LOG_START, LOG_END) segment. - break; - } - int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0); - if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) { - // No feedback sent/received for more than 2000 ms. - Alert_RtcpLogTimeGap(direction, - config_.GetCallTimeSec(rtcp.log_time_us()), - duration / 1000); - } - last_rtcp_time.emplace(rtcp.log_time_us()); - } - } -} - -// TODO(terelius): Notifications could possibly be generated by the same code -// that produces the graphs. There is some code duplication that could be -// avoided, but that might be solved anyway when we move functionality from the -// analyzer to the parser. -void EventLogAnalyzer::CreateTriageNotifications() { - CreateStreamGapAlerts(kIncomingPacket); - CreateStreamGapAlerts(kOutgoingPacket); - CreateTransmissionGapAlerts(kIncomingPacket); - CreateTransmissionGapAlerts(kOutgoingPacket); - - int64_t end_time_us = log_segments_.empty() - ? std::numeric_limits<int64_t>::max() - : log_segments_.front().second; - - constexpr double kMaxLossFraction = 0.05; - // Loss feedback - int64_t total_lost_packets = 0; - int64_t total_expected_packets = 0; - for (auto& bwe_update : parsed_log_.bwe_loss_updates()) { - if (bwe_update.log_time_us() > end_time_us) { - // Only process the first (LOG_START, LOG_END) segment. - break; - } - int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 * - bwe_update.expected_packets; - total_lost_packets += lost_packets; - total_expected_packets += bwe_update.expected_packets; - } - double avg_outgoing_loss = - static_cast<double>(total_lost_packets) / total_expected_packets; - if (avg_outgoing_loss > kMaxLossFraction) { - Alert_OutgoingHighLoss(avg_outgoing_loss); - } -} - } // namespace webrtc diff --git a/rtc_tools/rtc_event_log_visualizer/analyzer.h b/rtc_tools/rtc_event_log_visualizer/analyzer.h index 1e09109959..ebdfdcc41c 100644 --- a/rtc_tools/rtc_event_log_visualizer/analyzer.h +++ b/rtc_tools/rtc_event_log_visualizer/analyzer.h @@ -21,41 +21,18 @@ #include "logging/rtc_event_log/rtc_event_log_parser.h" #include "modules/audio_coding/neteq/tools/neteq_stats_getter.h" #include "rtc_base/strings/string_builder.h" +#include "rtc_tools/rtc_event_log_visualizer/analyzer_common.h" #include "rtc_tools/rtc_event_log_visualizer/plot_base.h" -#include "rtc_tools/rtc_event_log_visualizer/triage_notifications.h" namespace webrtc { -class AnalyzerConfig { - public: - float GetCallTimeSec(int64_t timestamp_us) const { - int64_t offset = normalize_time_ ? begin_time_ : 0; - return static_cast<float>(timestamp_us - offset) / 1000000; - } - - float CallBeginTimeSec() const { return GetCallTimeSec(begin_time_); } - - float CallEndTimeSec() const { return GetCallTimeSec(end_time_); } - - // Window and step size used for calculating moving averages, e.g. bitrate. - // The generated data points will be |step_| microseconds apart. - // Only events occurring at most |window_duration_| microseconds before the - // current data point will be part of the average. - int64_t window_duration_; - int64_t step_; - - // First and last events of the log. - int64_t begin_time_; - int64_t end_time_; - bool normalize_time_; -}; - class EventLogAnalyzer { public: // The EventLogAnalyzer keeps a reference to the ParsedRtcEventLogNew for the // duration of its lifetime. The ParsedRtcEventLogNew must not be destroyed or // modified while the EventLogAnalyzer is being used. EventLogAnalyzer(const ParsedRtcEventLog& log, bool normalize_time); + EventLogAnalyzer(const ParsedRtcEventLog& log, const AnalyzerConfig& config); void CreatePacketGraph(PacketDirection direction, Plot* plot); @@ -138,55 +115,6 @@ class EventLogAnalyzer { void PrintNotifications(FILE* file); private: - struct LayerDescription { - LayerDescription(uint32_t ssrc, - uint8_t spatial_layer, - uint8_t temporal_layer) - : ssrc(ssrc), - spatial_layer(spatial_layer), - temporal_layer(temporal_layer) {} - bool operator<(const LayerDescription& other) const { - if (ssrc != other.ssrc) - return ssrc < other.ssrc; - if (spatial_layer != other.spatial_layer) - return spatial_layer < other.spatial_layer; - return temporal_layer < other.temporal_layer; - } - uint32_t ssrc; - uint8_t spatial_layer; - uint8_t temporal_layer; - }; - - bool IsRtxSsrc(PacketDirection direction, uint32_t ssrc) const { - if (direction == kIncomingPacket) { - return parsed_log_.incoming_rtx_ssrcs().find(ssrc) != - parsed_log_.incoming_rtx_ssrcs().end(); - } else { - return parsed_log_.outgoing_rtx_ssrcs().find(ssrc) != - parsed_log_.outgoing_rtx_ssrcs().end(); - } - } - - bool IsVideoSsrc(PacketDirection direction, uint32_t ssrc) const { - if (direction == kIncomingPacket) { - return parsed_log_.incoming_video_ssrcs().find(ssrc) != - parsed_log_.incoming_video_ssrcs().end(); - } else { - return parsed_log_.outgoing_video_ssrcs().find(ssrc) != - parsed_log_.outgoing_video_ssrcs().end(); - } - } - - bool IsAudioSsrc(PacketDirection direction, uint32_t ssrc) const { - if (direction == kIncomingPacket) { - return parsed_log_.incoming_audio_ssrcs().find(ssrc) != - parsed_log_.incoming_audio_ssrcs().end(); - } else { - return parsed_log_.outgoing_audio_ssrcs().find(ssrc) != - parsed_log_.outgoing_audio_ssrcs().end(); - } - } - template <typename NetEqStatsType> void CreateNetEqStatsGraphInternal( const NetEqStatsGetterMap& neteq_stats, @@ -201,82 +129,6 @@ class EventLogAnalyzer { const IterableType& packets, const std::string& label); - void CreateStreamGapAlerts(PacketDirection direction); - void CreateTransmissionGapAlerts(PacketDirection direction); - - std::string GetStreamName(PacketDirection direction, uint32_t ssrc) const { - char buffer[200]; - rtc::SimpleStringBuilder name(buffer); - if (IsAudioSsrc(direction, ssrc)) { - name << "Audio "; - } else if (IsVideoSsrc(direction, ssrc)) { - name << "Video "; - } else { - name << "Unknown "; - } - if (IsRtxSsrc(direction, ssrc)) { - name << "RTX "; - } - if (direction == kIncomingPacket) - name << "(In) "; - else - name << "(Out) "; - name << "SSRC " << ssrc; - return name.str(); - } - - std::string GetLayerName(LayerDescription layer) const { - char buffer[100]; - rtc::SimpleStringBuilder name(buffer); - name << "SSRC " << layer.ssrc << " sl " << layer.spatial_layer << ", tl " - << layer.temporal_layer; - return name.str(); - } - - void Alert_RtpLogTimeGap(PacketDirection direction, - float time_seconds, - int64_t duration) { - if (direction == kIncomingPacket) { - incoming_rtp_recv_time_gaps_.emplace_back(time_seconds, duration); - } else { - outgoing_rtp_send_time_gaps_.emplace_back(time_seconds, duration); - } - } - - void Alert_RtcpLogTimeGap(PacketDirection direction, - float time_seconds, - int64_t duration) { - if (direction == kIncomingPacket) { - incoming_rtcp_recv_time_gaps_.emplace_back(time_seconds, duration); - } else { - outgoing_rtcp_send_time_gaps_.emplace_back(time_seconds, duration); - } - } - - void Alert_SeqNumJump(PacketDirection direction, - float time_seconds, - uint32_t ssrc) { - if (direction == kIncomingPacket) { - incoming_seq_num_jumps_.emplace_back(time_seconds, ssrc); - } else { - outgoing_seq_num_jumps_.emplace_back(time_seconds, ssrc); - } - } - - void Alert_CaptureTimeJump(PacketDirection direction, - float time_seconds, - uint32_t ssrc) { - if (direction == kIncomingPacket) { - incoming_capture_time_jumps_.emplace_back(time_seconds, ssrc); - } else { - outgoing_capture_time_jumps_.emplace_back(time_seconds, ssrc); - } - } - - void Alert_OutgoingHighLoss(double avg_loss_fraction) { - outgoing_high_loss_alerts_.emplace_back(avg_loss_fraction); - } - std::string GetCandidatePairLogDescriptionFromId(uint32_t candidate_pair_id); const ParsedRtcEventLog& parsed_log_; @@ -285,20 +137,6 @@ class EventLogAnalyzer { // If left empty, all SSRCs will be considered relevant. std::vector<uint32_t> desired_ssrc_; - // Stores the timestamps for all log segments, in the form of associated start - // and end events. - std::vector<std::pair<int64_t, int64_t>> log_segments_; - - std::vector<IncomingRtpReceiveTimeGap> incoming_rtp_recv_time_gaps_; - std::vector<IncomingRtcpReceiveTimeGap> incoming_rtcp_recv_time_gaps_; - std::vector<OutgoingRtpSendTimeGap> outgoing_rtp_send_time_gaps_; - std::vector<OutgoingRtcpSendTimeGap> outgoing_rtcp_send_time_gaps_; - std::vector<IncomingSeqNumJump> incoming_seq_num_jumps_; - std::vector<IncomingCaptureTimeJump> incoming_capture_time_jumps_; - std::vector<OutgoingSeqNoJump> outgoing_seq_num_jumps_; - std::vector<OutgoingCaptureTimeJump> outgoing_capture_time_jumps_; - std::vector<OutgoingHighLoss> outgoing_high_loss_alerts_; - std::map<uint32_t, std::string> candidate_pair_desc_by_id_; AnalyzerConfig config_; diff --git a/rtc_tools/rtc_event_log_visualizer/analyzer_common.cc b/rtc_tools/rtc_event_log_visualizer/analyzer_common.cc new file mode 100644 index 0000000000..3d3ce5a4ac --- /dev/null +++ b/rtc_tools/rtc_event_log_visualizer/analyzer_common.cc @@ -0,0 +1,83 @@ + +/* + * Copyright (c) 2020 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#include "rtc_tools/rtc_event_log_visualizer/analyzer_common.h" + +namespace webrtc { + +bool IsRtxSsrc(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc) { + if (direction == kIncomingPacket) { + return parsed_log.incoming_rtx_ssrcs().find(ssrc) != + parsed_log.incoming_rtx_ssrcs().end(); + } else { + return parsed_log.outgoing_rtx_ssrcs().find(ssrc) != + parsed_log.outgoing_rtx_ssrcs().end(); + } +} + +bool IsVideoSsrc(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc) { + if (direction == kIncomingPacket) { + return parsed_log.incoming_video_ssrcs().find(ssrc) != + parsed_log.incoming_video_ssrcs().end(); + } else { + return parsed_log.outgoing_video_ssrcs().find(ssrc) != + parsed_log.outgoing_video_ssrcs().end(); + } +} + +bool IsAudioSsrc(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc) { + if (direction == kIncomingPacket) { + return parsed_log.incoming_audio_ssrcs().find(ssrc) != + parsed_log.incoming_audio_ssrcs().end(); + } else { + return parsed_log.outgoing_audio_ssrcs().find(ssrc) != + parsed_log.outgoing_audio_ssrcs().end(); + } +} + +std::string GetStreamName(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc) { + char buffer[200]; + rtc::SimpleStringBuilder name(buffer); + if (IsAudioSsrc(parsed_log, direction, ssrc)) { + name << "Audio "; + } else if (IsVideoSsrc(parsed_log, direction, ssrc)) { + name << "Video "; + } else { + name << "Unknown "; + } + if (IsRtxSsrc(parsed_log, direction, ssrc)) { + name << "RTX "; + } + if (direction == kIncomingPacket) + name << "(In) "; + else + name << "(Out) "; + name << "SSRC " << ssrc; + return name.str(); +} + +std::string GetLayerName(LayerDescription layer) { + char buffer[100]; + rtc::SimpleStringBuilder name(buffer); + name << "SSRC " << layer.ssrc << " sl " << layer.spatial_layer << ", tl " + << layer.temporal_layer; + return name.str(); +} + +} // namespace webrtc diff --git a/rtc_tools/rtc_event_log_visualizer/analyzer_common.h b/rtc_tools/rtc_event_log_visualizer/analyzer_common.h new file mode 100644 index 0000000000..3ac651e69a --- /dev/null +++ b/rtc_tools/rtc_event_log_visualizer/analyzer_common.h @@ -0,0 +1,79 @@ +/* + * Copyright (c) 2020 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#ifndef RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_ANALYZER_COMMON_H_ +#define RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_ANALYZER_COMMON_H_ + +#include <cstdint> +#include <string> + +#include "logging/rtc_event_log/rtc_event_log_parser.h" + +namespace webrtc { + +class AnalyzerConfig { + public: + float GetCallTimeSec(int64_t timestamp_us) const { + int64_t offset = normalize_time_ ? begin_time_ : 0; + return static_cast<float>(timestamp_us - offset) / 1000000; + } + + float CallBeginTimeSec() const { return GetCallTimeSec(begin_time_); } + + float CallEndTimeSec() const { return GetCallTimeSec(end_time_); } + + // Window and step size used for calculating moving averages, e.g. bitrate. + // The generated data points will be |step_| microseconds apart. + // Only events occurring at most |window_duration_| microseconds before the + // current data point will be part of the average. + int64_t window_duration_; + int64_t step_; + + // First and last events of the log. + int64_t begin_time_; + int64_t end_time_; + bool normalize_time_; +}; + +struct LayerDescription { + LayerDescription(uint32_t ssrc, uint8_t spatial_layer, uint8_t temporal_layer) + : ssrc(ssrc), + spatial_layer(spatial_layer), + temporal_layer(temporal_layer) {} + bool operator<(const LayerDescription& other) const { + if (ssrc != other.ssrc) + return ssrc < other.ssrc; + if (spatial_layer != other.spatial_layer) + return spatial_layer < other.spatial_layer; + return temporal_layer < other.temporal_layer; + } + uint32_t ssrc; + uint8_t spatial_layer; + uint8_t temporal_layer; +}; + +bool IsRtxSsrc(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc); +bool IsVideoSsrc(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc); +bool IsAudioSsrc(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc); + +std::string GetStreamName(const ParsedRtcEventLog& parsed_log, + PacketDirection direction, + uint32_t ssrc); +std::string GetLayerName(LayerDescription layer); + +} // namespace webrtc + +#endif // RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_ANALYZER_COMMON_H_ diff --git a/rtc_tools/rtc_event_log_visualizer/main.cc b/rtc_tools/rtc_event_log_visualizer/main.cc index eb36b2679e..21768c92d1 100644 --- a/rtc_tools/rtc_event_log_visualizer/main.cc +++ b/rtc_tools/rtc_event_log_visualizer/main.cc @@ -30,6 +30,7 @@ #include "modules/rtp_rtcp/source/rtcp_packet/report_block.h" #include "rtc_base/checks.h" #include "rtc_base/logging.h" +#include "rtc_tools/rtc_event_log_visualizer/alerts.h" #include "rtc_tools/rtc_event_log_visualizer/analyzer.h" #include "rtc_tools/rtc_event_log_visualizer/plot_base.h" #include "rtc_tools/rtc_event_log_visualizer/plot_protobuf.h" @@ -194,9 +195,9 @@ int main(int argc, char* argv[]) { "A tool for visualizing WebRTC event logs.\n" "Example usage:\n" "./event_log_visualizer <logfile> | python\n"); - absl::FlagsUsageConfig config; - config.contains_help_flags = &ContainsHelppackageFlags; - absl::SetFlagsUsageConfig(config); + absl::FlagsUsageConfig flag_config; + flag_config.contains_help_flags = &ContainsHelppackageFlags; + absl::SetFlagsUsageConfig(flag_config); std::vector<char*> args = absl::ParseCommandLine(argc, argv); // Print RTC_LOG warnings and errors even in release builds. @@ -261,8 +262,20 @@ int main(int argc, char* argv[]) { } } - webrtc::EventLogAnalyzer analyzer(parsed_log, - absl::GetFlag(FLAGS_normalize_time)); + webrtc::AnalyzerConfig config; + config.window_duration_ = 250000; + config.step_ = 10000; + config.normalize_time_ = absl::GetFlag(FLAGS_normalize_time); + config.begin_time_ = parsed_log.first_timestamp(); + config.end_time_ = parsed_log.last_timestamp(); + if (config.end_time_ < config.begin_time_) { + RTC_LOG(LS_WARNING) << "Log end time " << config.end_time_ + << " not after begin time " << config.begin_time_ + << ". Nothing to analyze. Is the log broken?"; + return -1; + } + + webrtc::EventLogAnalyzer analyzer(parsed_log, config); std::unique_ptr<webrtc::PlotCollection> collection; if (absl::GetFlag(FLAGS_protobuf_output)) { collection.reset(new webrtc::ProtobufPlotCollection()); @@ -614,8 +627,9 @@ int main(int argc, char* argv[]) { collection->Draw(); if (absl::GetFlag(FLAGS_print_triage_alerts)) { - analyzer.CreateTriageNotifications(); - analyzer.PrintNotifications(stderr); + webrtc::TriageHelper triage_alerts(config); + triage_alerts.AnalyzeLog(parsed_log); + triage_alerts.Print(stderr); } return 0; diff --git a/rtc_tools/rtc_event_log_visualizer/triage_notifications.h b/rtc_tools/rtc_event_log_visualizer/triage_notifications.h deleted file mode 100644 index 23b31ece42..0000000000 --- a/rtc_tools/rtc_event_log_visualizer/triage_notifications.h +++ /dev/null @@ -1,158 +0,0 @@ -/* - * Copyright (c) 2017 The WebRTC project authors. All Rights Reserved. - * - * Use of this source code is governed by a BSD-style license - * that can be found in the LICENSE file in the root of the source - * tree. An additional intellectual property rights grant can be found - * in the file PATENTS. All contributing project authors may - * be found in the AUTHORS file in the root of the source tree. - */ - -#ifndef RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_TRIAGE_NOTIFICATIONS_H_ -#define RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_TRIAGE_NOTIFICATIONS_H_ - -#include <string> - -namespace webrtc { - -class IncomingRtpReceiveTimeGap { - public: - IncomingRtpReceiveTimeGap(float time_seconds, int64_t duration) - : time_seconds_(time_seconds), duration_(duration) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("No RTP packets received for ") + - std::to_string(duration_) + std::string(" ms"); - } - - private: - float time_seconds_; - int64_t duration_; -}; - -class IncomingRtcpReceiveTimeGap { - public: - IncomingRtcpReceiveTimeGap(float time_seconds, int64_t duration) - : time_seconds_(time_seconds), duration_(duration) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("No RTCP packets received for ") + - std::to_string(duration_) + std::string(" ms"); - } - - private: - float time_seconds_; - int64_t duration_; -}; - -class OutgoingRtpSendTimeGap { - public: - OutgoingRtpSendTimeGap(float time_seconds, int64_t duration) - : time_seconds_(time_seconds), duration_(duration) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("No RTP packets sent for ") + std::to_string(duration_) + - std::string(" ms"); - } - - private: - float time_seconds_; - int64_t duration_; -}; - -class OutgoingRtcpSendTimeGap { - public: - OutgoingRtcpSendTimeGap(float time_seconds, int64_t duration) - : time_seconds_(time_seconds), duration_(duration) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("No RTCP packets sent for ") + - std::to_string(duration_) + std::string(" ms"); - } - - private: - float time_seconds_; - int64_t duration_; -}; - -class IncomingSeqNumJump { - public: - IncomingSeqNumJump(float time_seconds, uint32_t ssrc) - : time_seconds_(time_seconds), ssrc_(ssrc) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("Sequence number jumps on incoming SSRC ") + - std::to_string(ssrc_); - } - - private: - float time_seconds_; - - uint32_t ssrc_; -}; - -class IncomingCaptureTimeJump { - public: - IncomingCaptureTimeJump(float time_seconds, uint32_t ssrc) - : time_seconds_(time_seconds), ssrc_(ssrc) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("Capture timestamp jumps on incoming SSRC ") + - std::to_string(ssrc_); - } - - private: - float time_seconds_; - - uint32_t ssrc_; -}; - -class OutgoingSeqNoJump { - public: - OutgoingSeqNoJump(float time_seconds, uint32_t ssrc) - : time_seconds_(time_seconds), ssrc_(ssrc) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("Sequence number jumps on outgoing SSRC ") + - std::to_string(ssrc_); - } - - private: - float time_seconds_; - - uint32_t ssrc_; -}; - -class OutgoingCaptureTimeJump { - public: - OutgoingCaptureTimeJump(float time_seconds, uint32_t ssrc) - : time_seconds_(time_seconds), ssrc_(ssrc) {} - float Time() const { return time_seconds_; } - std::string ToString() const { - return std::string("Capture timestamp jumps on outgoing SSRC ") + - std::to_string(ssrc_); - } - - private: - float time_seconds_; - - uint32_t ssrc_; -}; - -class OutgoingHighLoss { - public: - explicit OutgoingHighLoss(double avg_loss_fraction) - : avg_loss_fraction_(avg_loss_fraction) {} - std::string ToString() const { - return std::string("High average loss (") + - std::to_string(avg_loss_fraction_ * 100) + - std::string("%) across the call."); - } - - private: - double avg_loss_fraction_; -}; - -} // namespace webrtc - -#endif // RTC_TOOLS_RTC_EVENT_LOG_VISUALIZER_TRIAGE_NOTIFICATIONS_H_ |