blob: f2d956479588bbbe2a1248ee661b7d2e8754e99a [file] [log] [blame]
Bjorn Terelius48b82792020-05-19 10:57:24 +02001/*
2 * Copyright (c) 2020 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/alerts.h"
12
13#include <stdio.h>
14
15#include <algorithm>
16#include <limits>
17#include <map>
18#include <string>
19
20#include "logging/rtc_event_log/rtc_event_processor.h"
21#include "rtc_base/checks.h"
22#include "rtc_base/format_macros.h"
23#include "rtc_base/logging.h"
24#include "rtc_base/numerics/sequence_number_util.h"
25#include "rtc_base/strings/string_builder.h"
26
27namespace webrtc {
28
29void TriageHelper::Print(FILE* file) {
30 fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
31 for (const auto& alert : triage_alerts_) {
Bjorn Tereliusb9148192020-05-19 14:30:35 +020032 fprintf(file, "%d %s. First occurrence at %3.3lf\n", alert.second.count,
33 alert.second.explanation.c_str(), alert.second.first_occurrence);
Bjorn Terelius48b82792020-05-19 10:57:24 +020034 }
35 fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
36}
37
38void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log,
39 PacketDirection direction) {
40 // With 100 packets/s (~800kbps), false positives would require 10 s without
41 // data.
42 constexpr int64_t kMaxSeqNumJump = 1000;
43 // With a 90 kHz clock, false positives would require 10 s without data.
Bjorn Tereliusb9148192020-05-19 14:30:35 +020044 constexpr int64_t kTicksPerMillisec = 90;
45 constexpr int64_t kCaptureTimeGraceMs = 10000;
Bjorn Terelius48b82792020-05-19 10:57:24 +020046
47 std::string seq_num_explanation =
48 direction == kIncomingPacket
49 ? "Incoming RTP sequence number jumps more than 1000. Counter may "
50 "have been reset or rewritten incorrectly in a group call."
51 : "Outgoing RTP sequence number jumps more than 1000. Counter may "
52 "have been reset.";
53 std::string capture_time_explanation =
54 direction == kIncomingPacket ? "Incoming capture time jumps more than "
55 "10s. Clock might have been reset."
56 : "Outgoing capture time jumps more than "
57 "10s. Clock might have been reset.";
58 TriageAlertType seq_num_alert = direction == kIncomingPacket
59 ? TriageAlertType::kIncomingSeqNumJump
60 : TriageAlertType::kOutgoingSeqNumJump;
61 TriageAlertType capture_time_alert =
62 direction == kIncomingPacket ? TriageAlertType::kIncomingCaptureTimeJump
63 : TriageAlertType::kOutgoingCaptureTimeJump;
64
65 const int64_t segment_end_us =
66 parsed_log.log_segments().empty()
67 ? std::numeric_limits<int64_t>::max()
68 : parsed_log.log_segments().front().stop_time_us();
69
70 // Check for gaps in sequence numbers and capture timestamps.
71 for (const auto& stream : parsed_log.rtp_packets_by_ssrc(direction)) {
72 if (IsRtxSsrc(parsed_log, direction, stream.ssrc)) {
73 continue;
74 }
Bjorn Tereliusb9148192020-05-19 14:30:35 +020075 auto packets = stream.packet_view;
76 if (packets.empty()) {
77 continue;
78 }
Bjorn Terelius48b82792020-05-19 10:57:24 +020079 SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
Bjorn Tereliusb9148192020-05-19 14:30:35 +020080 int64_t last_seq_num =
81 seq_num_unwrapper.Unwrap(packets[0].header.sequenceNumber);
Bjorn Terelius48b82792020-05-19 10:57:24 +020082 SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
Bjorn Tereliusb9148192020-05-19 14:30:35 +020083 int64_t last_capture_time =
84 capture_time_unwrapper.Unwrap(packets[0].header.timestamp);
85 int64_t last_log_time_ms = packets[0].log_time_ms();
86 for (const auto& packet : packets) {
Bjorn Terelius48b82792020-05-19 10:57:24 +020087 if (packet.log_time_us() > segment_end_us) {
88 // Only process the first (LOG_START, LOG_END) segment.
89 break;
90 }
91
92 int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
Bjorn Tereliusb9148192020-05-19 14:30:35 +020093 if (std::abs(seq_num - last_seq_num) > kMaxSeqNumJump) {
Bjorn Terelius48b82792020-05-19 10:57:24 +020094 Alert(seq_num_alert, config_.GetCallTimeSec(packet.log_time_us()),
95 seq_num_explanation);
96 }
Bjorn Tereliusb9148192020-05-19 14:30:35 +020097 last_seq_num = seq_num;
Bjorn Terelius48b82792020-05-19 10:57:24 +020098
99 int64_t capture_time =
100 capture_time_unwrapper.Unwrap(packet.header.timestamp);
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200101 if (std::abs(capture_time - last_capture_time) >
102 kTicksPerMillisec *
103 (kCaptureTimeGraceMs + packet.log_time_ms() - last_log_time_ms)) {
Bjorn Terelius48b82792020-05-19 10:57:24 +0200104 Alert(capture_time_alert, config_.GetCallTimeSec(packet.log_time_us()),
105 capture_time_explanation);
106 }
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200107 last_capture_time = capture_time;
Bjorn Terelius48b82792020-05-19 10:57:24 +0200108 }
109 }
110}
111
112void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log,
113 PacketDirection direction) {
114 constexpr int64_t kMaxRtpTransmissionGap = 500000;
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200115 constexpr int64_t kMaxRtcpTransmissionGap = 3000000;
Bjorn Terelius48b82792020-05-19 10:57:24 +0200116 std::string rtp_explanation =
117 direction == kIncomingPacket
118 ? "No RTP packets received for more than 500ms. This indicates a "
119 "network problem. Temporary video freezes and choppy or robotic "
120 "audio is unavoidable. Unnecessary BWE drops is a known issue."
121 : "No RTP packets sent for more than 500 ms. This might be an issue "
122 "with the pacer.";
123 std::string rtcp_explanation =
124 direction == kIncomingPacket
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200125 ? "No RTCP packets received for more than 3 s. Could be a longer "
Bjorn Terelius48b82792020-05-19 10:57:24 +0200126 "connection outage"
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200127 : "No RTCP packets sent for more than 3 s. This is most likely a "
128 "bug.";
Bjorn Terelius48b82792020-05-19 10:57:24 +0200129 TriageAlertType rtp_alert = direction == kIncomingPacket
130 ? TriageAlertType::kIncomingRtpGap
131 : TriageAlertType::kOutgoingRtpGap;
132 TriageAlertType rtcp_alert = direction == kIncomingPacket
133 ? TriageAlertType::kIncomingRtcpGap
134 : TriageAlertType::kOutgoingRtcpGap;
135
136 const int64_t segment_end_us =
137 parsed_log.log_segments().empty()
138 ? std::numeric_limits<int64_t>::max()
139 : parsed_log.log_segments().front().stop_time_us();
140
141 // TODO(terelius): The parser could provide a list of all packets, ordered
142 // by time, for each direction.
143 std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
144 for (const auto& stream : parsed_log.rtp_packets_by_ssrc(direction)) {
145 for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
146 rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
147 }
148 absl::optional<int64_t> last_rtp_time;
149 for (const auto& kv : rtp_in_direction) {
150 int64_t timestamp = kv.first;
151 if (timestamp > segment_end_us) {
152 // Only process the first (LOG_START, LOG_END) segment.
153 break;
154 }
155 int64_t duration = timestamp - last_rtp_time.value_or(0);
156 if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
157 // No packet sent/received for more than 500 ms.
158 Alert(rtp_alert, config_.GetCallTimeSec(timestamp), rtp_explanation);
159 }
160 last_rtp_time.emplace(timestamp);
161 }
162
163 absl::optional<int64_t> last_rtcp_time;
164 if (direction == kIncomingPacket) {
165 for (const auto& rtcp : parsed_log.incoming_rtcp_packets()) {
166 if (rtcp.log_time_us() > segment_end_us) {
167 // Only process the first (LOG_START, LOG_END) segment.
168 break;
169 }
170 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
171 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
172 // No feedback sent/received for more than 2000 ms.
173 Alert(rtcp_alert, config_.GetCallTimeSec(rtcp.log_time_us()),
174 rtcp_explanation);
175 }
176 last_rtcp_time.emplace(rtcp.log_time_us());
177 }
178 } else {
179 for (const auto& rtcp : parsed_log.outgoing_rtcp_packets()) {
180 if (rtcp.log_time_us() > segment_end_us) {
181 // Only process the first (LOG_START, LOG_END) segment.
182 break;
183 }
184 int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
185 if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
186 // No feedback sent/received for more than 2000 ms.
187 Alert(rtcp_alert, config_.GetCallTimeSec(rtcp.log_time_us()),
188 rtcp_explanation);
189 }
190 last_rtcp_time.emplace(rtcp.log_time_us());
191 }
192 }
193}
194
195// TODO(terelius): Notifications could possibly be generated by the same code
196// that produces the graphs. There is some code duplication that could be
197// avoided, but that might be solved anyway when we move functionality from the
198// analyzer to the parser.
199void TriageHelper::AnalyzeLog(const ParsedRtcEventLog& parsed_log) {
200 AnalyzeStreamGaps(parsed_log, kIncomingPacket);
201 AnalyzeStreamGaps(parsed_log, kOutgoingPacket);
202 AnalyzeTransmissionGaps(parsed_log, kIncomingPacket);
203 AnalyzeTransmissionGaps(parsed_log, kOutgoingPacket);
204
205 const int64_t segment_end_us =
206 parsed_log.log_segments().empty()
207 ? std::numeric_limits<int64_t>::max()
208 : parsed_log.log_segments().front().stop_time_us();
209
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200210 int64_t first_occurrence = parsed_log.last_timestamp();
Bjorn Terelius48b82792020-05-19 10:57:24 +0200211 constexpr double kMaxLossFraction = 0.05;
212 // Loss feedback
213 int64_t total_lost_packets = 0;
214 int64_t total_expected_packets = 0;
215 for (auto& bwe_update : parsed_log.bwe_loss_updates()) {
216 if (bwe_update.log_time_us() > segment_end_us) {
217 // Only process the first (LOG_START, LOG_END) segment.
218 break;
219 }
220 int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
221 bwe_update.expected_packets;
222 total_lost_packets += lost_packets;
223 total_expected_packets += bwe_update.expected_packets;
224 if (bwe_update.fraction_lost >= 255 * kMaxLossFraction) {
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200225 first_occurrence = std::min(first_occurrence, bwe_update.log_time_us());
Bjorn Terelius48b82792020-05-19 10:57:24 +0200226 }
227 }
228 double avg_outgoing_loss =
229 static_cast<double>(total_lost_packets) / total_expected_packets;
230 if (avg_outgoing_loss > kMaxLossFraction) {
Bjorn Tereliusb9148192020-05-19 14:30:35 +0200231 Alert(TriageAlertType::kOutgoingHighLoss, first_occurrence,
Bjorn Terelius48b82792020-05-19 10:57:24 +0200232 "More than 5% of outgoing packets lost.");
233 }
234}
235
236} // namespace webrtc