diff options
Diffstat (limited to '')
-rw-r--r-- | third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc | 236 |
1 files changed, 236 insertions, 0 deletions
diff --git a/third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc b/third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc new file mode 100644 index 0000000000..a9f50cdd5c --- /dev/null +++ b/third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc @@ -0,0 +1,236 @@ +/* + * 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/logging.h" +#include "rtc_base/numerics/sequence_number_unwrapper.h" +#include "rtc_base/strings/string_builder.h" + +namespace webrtc { + +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 kTicksPerMillisec = 90; + constexpr int64_t kCaptureTimeGraceMs = 10000; + + 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.first_log_segment().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; + } + auto packets = stream.packet_view; + if (packets.empty()) { + continue; + } + SeqNumUnwrapper<uint16_t> seq_num_unwrapper; + int64_t last_seq_num = + seq_num_unwrapper.Unwrap(packets[0].header.sequenceNumber); + SeqNumUnwrapper<uint32_t> capture_time_unwrapper; + int64_t last_capture_time = + capture_time_unwrapper.Unwrap(packets[0].header.timestamp); + int64_t last_log_time_ms = packets[0].log_time_ms(); + for (const auto& packet : packets) { + 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 (std::abs(seq_num - last_seq_num) > kMaxSeqNumJump) { + Alert(seq_num_alert, config_.GetCallTimeSec(packet.log_time()), + seq_num_explanation); + } + last_seq_num = seq_num; + + int64_t capture_time = + capture_time_unwrapper.Unwrap(packet.header.timestamp); + if (std::abs(capture_time - last_capture_time) > + kTicksPerMillisec * + (kCaptureTimeGraceMs + packet.log_time_ms() - last_log_time_ms)) { + Alert(capture_time_alert, config_.GetCallTimeSec(packet.log_time()), + capture_time_explanation); + } + last_capture_time = capture_time; + } + } +} + +void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log, + PacketDirection direction) { + constexpr int64_t kMaxRtpTransmissionGap = 500000; + constexpr int64_t kMaxRtcpTransmissionGap = 3000000; + 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 3 s. Could be a longer " + "connection outage" + : "No RTCP packets sent for more than 3 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.first_log_segment().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::Micros(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()), + 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()), + 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.first_log_segment().stop_time_us(); + + Timestamp first_occurrence = 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_occurrence = std::min(first_occurrence, bwe_update.log_time()); + } + } + double avg_outgoing_loss = + static_cast<double>(total_lost_packets) / total_expected_packets; + if (avg_outgoing_loss > kMaxLossFraction) { + Alert(TriageAlertType::kOutgoingHighLoss, + config_.GetCallTimeSec(first_occurrence), + "More than 5% of outgoing packets lost."); + } +} + +void TriageHelper::Print(FILE* file) { + fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n"); + for (const auto& alert : triage_alerts_) { + fprintf(file, "%d %s. First occurrence at %3.3lf\n", alert.second.count, + alert.second.explanation.c_str(), alert.second.first_occurrence); + } + fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n"); +} + +void TriageHelper::ProcessAlerts( + std::function<void(int, float, std::string)> f) { + for (const auto& alert : triage_alerts_) { + f(alert.second.count, alert.second.first_occurrence, + alert.second.explanation); + } +} + +} // namespace webrtc |