zqz/platform-external-webrtc
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Reduce alert spam in rtc_event_log_visualizer

Browse Source 
Bug: webrtc:11564
Change-Id: I4fdd6284b35cedded4d8b623dc0b7f8e1534c495
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/175649
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Reviewed-by: Mirko Bonadei <mbonadei@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31324}
This commit is contained in:
Bjorn Terelius
2020-05-19 14:30:35 +02:00
committed by Commit Bot
parent c5324fb7bd
commit b914819944
3 changed files with 31 additions and 21 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
logging/rtc_event_log/rtc_event_log_parser.h
View File

@ -193,6 +193,8 @@ class PacketView {
size_t size() const { return num_elements_; } size_t size() const { return num_elements_; }
bool empty() const { return num_elements_ == 0; }
T& operator[](size_t i) { T& operator[](size_t i) {
auto elem_ptr = data_ + i * element_size_; auto elem_ptr = data_ + i * element_size_;
return *reinterpret_cast<T*>(elem_ptr); return *reinterpret_cast<T*>(elem_ptr);

46
rtc_tools/rtc_event_log_visualizer/alerts.cc
View File

@ -29,8 +29,8 @@ namespace webrtc {
void TriageHelper::Print(FILE* file) { void TriageHelper::Print(FILE* file) {
fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n"); fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
for (const auto& alert : triage_alerts_) { for (const auto& alert : triage_alerts_) {
fprintf(file, "%d %s. First occurence at %3.3lf\n", alert.second.count, fprintf(file, "%d %s. First occurrence at %3.3lf\n", alert.second.count,
alert.second.explanation.c_str(), alert.second.first_occurence); alert.second.explanation.c_str(), alert.second.first_occurrence);
} }
fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n"); fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
} }
@ -41,7 +41,8 @@ void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log,
// data. // data.
constexpr int64_t kMaxSeqNumJump = 1000; constexpr int64_t kMaxSeqNumJump = 1000;
// With a 90 kHz clock, false positives would require 10 s without data. // With a 90 kHz clock, false positives would require 10 s without data.
constexpr int64_t kMaxCaptureTimeJump = 900000; constexpr int64_t kTicksPerMillisec = 90;
constexpr int64_t kCaptureTimeGraceMs = 10000;
std::string seq_num_explanation = std::string seq_num_explanation =
direction == kIncomingPacket direction == kIncomingPacket
@ -71,33 +72,39 @@ void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log,
if (IsRtxSsrc(parsed_log, direction, stream.ssrc)) { if (IsRtxSsrc(parsed_log, direction, stream.ssrc)) {
continue; continue;
} }
auto packets = stream.packet_view;
if (packets.empty()) {
continue;
}
SeqNumUnwrapper<uint16_t> seq_num_unwrapper; SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
absl::optional<int64_t> last_seq_num; int64_t last_seq_num =
seq_num_unwrapper.Unwrap(packets[0].header.sequenceNumber);
SeqNumUnwrapper<uint32_t> capture_time_unwrapper; SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
absl::optional<int64_t> last_capture_time; int64_t last_capture_time =
for (const auto& packet : stream.packet_view) { 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) { if (packet.log_time_us() > segment_end_us) {
// Only process the first (LOG_START, LOG_END) segment. // Only process the first (LOG_START, LOG_END) segment.
break; break;
} }
int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber); int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
if (last_seq_num.has_value() && if (std::abs(seq_num - last_seq_num) > kMaxSeqNumJump) {
std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
Alert(seq_num_alert, config_.GetCallTimeSec(packet.log_time_us()), Alert(seq_num_alert, config_.GetCallTimeSec(packet.log_time_us()),
seq_num_explanation); seq_num_explanation);
} }
last_seq_num.emplace(seq_num); last_seq_num = seq_num;
int64_t capture_time = int64_t capture_time =
capture_time_unwrapper.Unwrap(packet.header.timestamp); capture_time_unwrapper.Unwrap(packet.header.timestamp);
if (last_capture_time.has_value() && if (std::abs(capture_time - last_capture_time) >
std::abs(capture_time - last_capture_time.value()) > kTicksPerMillisec *
kMaxCaptureTimeJump) { (kCaptureTimeGraceMs + packet.log_time_ms() - last_log_time_ms)) {
Alert(capture_time_alert, config_.GetCallTimeSec(packet.log_time_us()), Alert(capture_time_alert, config_.GetCallTimeSec(packet.log_time_us()),
capture_time_explanation); capture_time_explanation);
} }
last_capture_time.emplace(capture_time); last_capture_time = capture_time;
} }
} }
} }
@ -105,7 +112,7 @@ void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log,
void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log, void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log,
PacketDirection direction) { PacketDirection direction) {
constexpr int64_t kMaxRtpTransmissionGap = 500000; constexpr int64_t kMaxRtpTransmissionGap = 500000;
constexpr int64_t kMaxRtcpTransmissionGap = 2000000; constexpr int64_t kMaxRtcpTransmissionGap = 3000000;
std::string rtp_explanation = std::string rtp_explanation =
direction == kIncomingPacket direction == kIncomingPacket
? "No RTP packets received for more than 500ms. This indicates a " ? "No RTP packets received for more than 500ms. This indicates a "
@ -115,9 +122,10 @@ void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log,
"with the pacer."; "with the pacer.";
std::string rtcp_explanation = std::string rtcp_explanation =
direction == kIncomingPacket direction == kIncomingPacket
? "No RTCP packets received for more than 2 s. Could be a longer " ? "No RTCP packets received for more than 3 s. Could be a longer "
"connection outage" "connection outage"
: "No RTCP sent for more than 2 s. This is most likely a bug."; : "No RTCP packets sent for more than 3 s. This is most likely a "
"bug.";
TriageAlertType rtp_alert = direction == kIncomingPacket TriageAlertType rtp_alert = direction == kIncomingPacket
? TriageAlertType::kIncomingRtpGap ? TriageAlertType::kIncomingRtpGap
: TriageAlertType::kOutgoingRtpGap; : TriageAlertType::kOutgoingRtpGap;
@ -199,7 +207,7 @@ void TriageHelper::AnalyzeLog(const ParsedRtcEventLog& parsed_log) {
? std::numeric_limits<int64_t>::max() ? std::numeric_limits<int64_t>::max()
: parsed_log.log_segments().front().stop_time_us(); : parsed_log.log_segments().front().stop_time_us();
int64_t first_occurence = parsed_log.last_timestamp(); int64_t first_occurrence = parsed_log.last_timestamp();
constexpr double kMaxLossFraction = 0.05; constexpr double kMaxLossFraction = 0.05;
// Loss feedback // Loss feedback
int64_t total_lost_packets = 0; int64_t total_lost_packets = 0;
@ -214,13 +222,13 @@ void TriageHelper::AnalyzeLog(const ParsedRtcEventLog& parsed_log) {
total_lost_packets += lost_packets; total_lost_packets += lost_packets;
total_expected_packets += bwe_update.expected_packets; total_expected_packets += bwe_update.expected_packets;
if (bwe_update.fraction_lost >= 255 * kMaxLossFraction) { if (bwe_update.fraction_lost >= 255 * kMaxLossFraction) {
first_occurence = std::min(first_occurence, bwe_update.log_time_us()); first_occurrence = std::min(first_occurrence, bwe_update.log_time_us());
} }
} }
double avg_outgoing_loss = double avg_outgoing_loss =
static_cast<double>(total_lost_packets) / total_expected_packets; static_cast<double>(total_lost_packets) / total_expected_packets;
if (avg_outgoing_loss > kMaxLossFraction) { if (avg_outgoing_loss > kMaxLossFraction) {
Alert(TriageAlertType::kOutgoingHighLoss, first_occurence, Alert(TriageAlertType::kOutgoingHighLoss, first_occurrence,
"More than 5% of outgoing packets lost."); "More than 5% of outgoing packets lost.");
} }
} }

4
rtc_tools/rtc_event_log_visualizer/alerts.h
View File

@ -41,7 +41,7 @@ enum class TriageAlertType {
struct TriageAlert { struct TriageAlert {
TriageAlertType type = TriageAlertType::kUnknown; TriageAlertType type = TriageAlertType::kUnknown;
int count = 0; int count = 0;
float first_occurence = -1; float first_occurrence = -1;
std::string explanation; std::string explanation;
}; };
@ -70,7 +70,7 @@ class TriageHelper {
if (it == triage_alerts_.end()) { if (it == triage_alerts_.end()) {
TriageAlert alert; TriageAlert alert;
alert.type = type; alert.type = type;
alert.first_occurence = time_seconds; alert.first_occurrence = time_seconds;
alert.count = 1; alert.count = 1;
alert.explanation = std::string(explanation); alert.explanation = std::string(explanation);
triage_alerts_.insert(std::make_pair(type, alert)); triage_alerts_.insert(std::make_pair(type, alert));