Aid triaging of bugs by printing notifications about interesting parts of an event log.
Notifications are printed for gaps in seq number, capture timestamp, arrival and send times for RTP and RTCP, and high average loss.
The notifications are printed to stderr by default, but internally they are represented as subclasses to a TriageNotification base class in order to facilitate other output formats.
Initially, this is only run if the event_log_visualizer is given the flag --print_triage_notifications.
Only the first (LOG_START, LOG_END) segment is processed.
Bug: webrtc:8383
Change-Id: If43ef7f115f622fa5552dc50951a11d5f9e3cbaa
Reviewed-on: https://webrtc-review.googlesource.com/8720
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Reviewed-by: Philip Eliasson <philipel@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#20974}diff --git a/rtc_tools/event_log_visualizer/analyzer.cc b/rtc_tools/event_log_visualizer/analyzer.cc
index 21bc580..792e6bb 100644
--- a/rtc_tools/event_log_visualizer/analyzer.cc
+++ b/rtc_tools/event_log_visualizer/analyzer.cc
@@ -539,6 +539,8 @@
// The log was missing the last LOG_END event. Fake it.
log_segments_.push_back(std::make_pair(*last_log_start, end_time_));
}
+ RTC_LOG(LS_INFO) << "Found " << log_segments_.size()
+ << " (LOG_START, LOG_END) segments in log.";
}
class BitrateObserver : public SendSideCongestionController::Observer,
@@ -641,6 +643,10 @@
return rtc::nullopt;
}
+float EventLogAnalyzer::ToCallTime(int64_t timestamp) const {
+ return static_cast<float>(timestamp - begin_time_) / 1000000;
+}
+
void EventLogAnalyzer::CreatePacketGraph(PacketDirection desired_direction,
Plot* plot) {
for (auto& kv : rtp_packets_) {
@@ -832,8 +838,8 @@
PointStyle::kHighlight);
const uint64_t kWindowUs = 1000000;
const uint64_t kStep = 1000000;
- SequenceNumberUnwrapper unwrapper_;
- SequenceNumberUnwrapper prior_unwrapper_;
+ SeqNumUnwrapper<uint16_t> unwrapper_;
+ SeqNumUnwrapper<uint16_t> prior_unwrapper_;
size_t window_index_begin = 0;
size_t window_index_end = 0;
int64_t highest_seq_number =
@@ -1950,5 +1956,164 @@
kTopMargin);
plot->SetTitle("NetEq timing");
}
+
+void EventLogAnalyzer::Notification(
+ std::unique_ptr<TriageNotification> notification) {
+ notifications_.push_back(std::move(notification));
+}
+
+void EventLogAnalyzer::PrintNotifications(FILE* file) {
+ if (notifications_.size() == 0)
+ return;
+ fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
+ for (const auto& notification : notifications_) {
+ rtc::Optional<float> call_timestamp = notification->Time();
+ if (call_timestamp.has_value()) {
+ fprintf(file, "%3.3lf s : %s\n", call_timestamp.value(),
+ notification->ToString().c_str());
+ } else {
+ fprintf(file, " : %s\n", notification->ToString().c_str());
+ }
+ }
+ fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
+}
+
+// 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() {
+ uint64_t end_time_us = log_segments_.empty()
+ ? std::numeric_limits<uint64_t>::max()
+ : log_segments_.front().second;
+ // Check for gaps in sequence numbers and capture timestamps.
+ for (auto& kv : rtp_packets_) {
+ StreamId stream_id = kv.first;
+ const std::vector<LoggedRtpPacket>& packet_stream = kv.second;
+
+ SeqNumUnwrapper<uint16_t> seq_no_unwrapper;
+ rtc::Optional<int64_t> last_seq_no;
+ SeqNumUnwrapper<uint32_t> timestamp_unwrapper;
+ rtc::Optional<int64_t> last_timestamp;
+ for (const auto& packet : packet_stream) {
+ if (packet.timestamp > end_time_us) {
+ // Only process the first (LOG_START, LOG_END) segment.
+ break;
+ }
+ int64_t seq_no = seq_no_unwrapper.Unwrap(packet.header.sequenceNumber);
+ if (last_seq_no.has_value() &&
+ std::abs(seq_no - last_seq_no.value()) > 1000) {
+ // With roughly 100 packets per second (~800kbps), this would require 10
+ // seconds without data to trigger incorrectly.
+ if (stream_id.GetDirection() == kIncomingPacket) {
+ Notification(rtc::MakeUnique<IncomingSeqNoJump>(
+ ToCallTime(packet.timestamp), packet.header.ssrc));
+ } else {
+ Notification(rtc::MakeUnique<OutgoingSeqNoJump>(
+ ToCallTime(packet.timestamp), packet.header.ssrc));
+ }
+ }
+ last_seq_no.emplace(seq_no);
+ int64_t timestamp = timestamp_unwrapper.Unwrap(packet.header.timestamp);
+ if (last_timestamp.has_value() &&
+ std::abs(timestamp - last_timestamp.value()) > 900000) {
+ // With a 90 kHz clock, this would require 10 seconds without data to
+ // trigger incorrectly.
+ if (stream_id.GetDirection() == kIncomingPacket) {
+ Notification(rtc::MakeUnique<IncomingCaptureTimeJump>(
+ ToCallTime(packet.timestamp), packet.header.ssrc));
+ } else {
+ Notification(rtc::MakeUnique<OutgoingCaptureTimeJump>(
+ ToCallTime(packet.timestamp), packet.header.ssrc));
+ }
+ }
+ last_timestamp.emplace(timestamp);
+ }
+ }
+
+ // Check for gaps in RTP and RTCP streams
+ for (const auto direction :
+ {PacketDirection::kIncomingPacket, PacketDirection::kOutgoingPacket}) {
+ // TODO(terelius): The parser could provide a list of all packets, ordered
+ // by time, for each direction.
+ std::multimap<uint64_t, const LoggedRtpPacket*> rtp_in_direction;
+ for (const auto& kv : rtp_packets_) {
+ if (kv.first.GetDirection() == direction) {
+ for (const LoggedRtpPacket& rtp_packet : kv.second)
+ rtp_in_direction.emplace(rtp_packet.timestamp, &rtp_packet);
+ }
+ }
+ rtc::Optional<uint64_t> last_rtp_packet;
+ for (const auto& kv : rtp_in_direction) {
+ uint64_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_packet.value_or(0);
+ if (last_rtp_packet.has_value() && duration > 500000) {
+ // No incoming packet for more than 500 ms.
+ if (direction == kIncomingPacket) {
+ Notification(rtc::MakeUnique<IncomingRtpReceiveTimeGap>(
+ ToCallTime(timestamp), duration / 1000));
+ } else {
+ Notification(rtc::MakeUnique<OutgoingRtpSendTimeGap>(
+ ToCallTime(timestamp), duration / 1000));
+ }
+ }
+ last_rtp_packet.emplace(timestamp);
+ }
+
+ // TODO(terelius): The parser could provide a list of all packets, ordered
+ // by time, for each direction.
+ std::multimap<uint64_t, const LoggedRtcpPacket*> rtcp_in_direction;
+ for (const auto& kv : rtcp_packets_) {
+ if (kv.first.GetDirection() == direction) {
+ for (const LoggedRtcpPacket& rtcp_packet : kv.second)
+ rtcp_in_direction.emplace(rtcp_packet.timestamp, &rtcp_packet);
+ }
+ }
+ rtc::Optional<uint64_t> last_incoming_rtcp_packet;
+ for (const auto& kv : rtcp_in_direction) {
+ uint64_t timestamp = kv.first;
+ if (timestamp > end_time_us) {
+ // Only process the first (LOG_START, LOG_END) segment.
+ break;
+ }
+ int64_t duration = timestamp - last_incoming_rtcp_packet.value_or(0);
+ if (last_incoming_rtcp_packet.has_value() && duration > 2000000) {
+ // No incoming feedback for more than 2000 ms.
+ if (direction == kIncomingPacket) {
+ Notification(rtc::MakeUnique<IncomingRtcpReceiveTimeGap>(
+ ToCallTime(timestamp), duration / 1000));
+ } else {
+ Notification(rtc::MakeUnique<OutgoingRtcpSendTimeGap>(
+ ToCallTime(timestamp), duration / 1000));
+ }
+ }
+ last_incoming_rtcp_packet.emplace(timestamp);
+ }
+ }
+
+ // Loss feedback
+ int64_t total_lost_packets = 0;
+ int64_t total_expected_packets = 0;
+ for (auto& bwe_update : bwe_loss_updates_) {
+ if (bwe_update.timestamp > end_time_us) {
+ // Only process the first (LOG_START, LOG_END) segment.
+ break;
+ }
+ int64_t lost_packets = static_cast<double>(bwe_update.fraction_loss) / 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 > 0.05) {
+ Notification(rtc::MakeUnique<OutgoingHighLoss>(avg_outgoing_loss));
+ }
+}
+
} // namespace plotting
} // namespace webrtc