From 0d1b28cf09de80c52e9241188dc390d7643a1d6e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn=20Terelius?= Date: Wed, 27 May 2020 20:25:06 +0200 Subject: [PATCH] Replace inconsistent log_segments() function in RTC event log parser MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bug: webrtc:11566 Change-Id: I739bbc29ae5423f3fedcc08e991e27fa0af840c5 Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/176081 Commit-Queue: Björn Terelius Reviewed-by: Mirko Bonadei Cr-Commit-Position: refs/heads/master@{#31371} --- .../encoder/rtc_event_log_encoder_unittest.cc | 11 +++-- logging/rtc_event_log/rtc_event_log_parser.cc | 47 +++++++++++-------- logging/rtc_event_log/rtc_event_log_parser.h | 7 +-- .../rtc_event_log/rtc_event_log_unittest.cc | 8 ++-- rtc_tools/rtc_event_log_visualizer/alerts.cc | 15 ++---- .../rtc_event_log_visualizer/analyzer.cc | 30 +++++------- 6 files changed, 59 insertions(+), 59 deletions(-) diff --git a/logging/rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc b/logging/rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc index 3059621690..cf85775f52 100644 --- a/logging/rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc +++ b/logging/rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc @@ -675,13 +675,18 @@ TEST_P(RtcEventLogEncoderTest, RtcEventLoggingStarted) { } TEST_P(RtcEventLogEncoderTest, RtcEventLoggingStopped) { - const int64_t timestamp_us = rtc::TimeMicros(); - std::string encoded = encoder_->EncodeLogEnd(timestamp_us); + const int64_t start_timestamp_us = rtc::TimeMicros(); + const int64_t start_utc_time_us = rtc::TimeUTCMicros(); + std::string encoded = + encoder_->EncodeLogStart(start_timestamp_us, start_utc_time_us); + + const int64_t stop_timestamp_us = rtc::TimeMicros(); + encoded += encoder_->EncodeLogEnd(stop_timestamp_us); ASSERT_TRUE(parsed_log_.ParseString(encoded).ok()); const auto& stop_log_events = parsed_log_.stop_log_events(); ASSERT_EQ(stop_log_events.size(), 1u); - verifier_.VerifyLoggedStopEvent(timestamp_us, stop_log_events[0]); + verifier_.VerifyLoggedStopEvent(stop_timestamp_us, stop_log_events[0]); } // TODO(eladalon/terelius): Test with multiple events in the batch. diff --git a/logging/rtc_event_log/rtc_event_log_parser.cc b/logging/rtc_event_log/rtc_event_log_parser.cc index a3982bad22..c88207607c 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.cc +++ b/logging/rtc_event_log/rtc_event_log_parser.cc @@ -1076,6 +1076,7 @@ void ParsedRtcEventLog::Clear() { first_timestamp_ = std::numeric_limits::max(); last_timestamp_ = std::numeric_limits::min(); + first_log_segment_ = LogSegment(0, std::numeric_limits::max()); incoming_rtp_extensions_maps_.clear(); outgoing_rtp_extensions_maps_.clear(); @@ -1214,31 +1215,37 @@ ParsedRtcEventLog::ParseStatus ParsedRtcEventLog::ParseStream( StoreFirstAndLastTimestamp(generic_packets_sent_); StoreFirstAndLastTimestamp(generic_packets_received_); StoreFirstAndLastTimestamp(generic_acks_received_); + StoreFirstAndLastTimestamp(remote_estimate_events_); - // TODO(terelius): This should be cleaned up. We could also handle - // a "missing" end event, by inserting the last previous regular - // event rather than the next start event. + // Stop events could be missing due to file size limits. If so, use the + // last event, or the next start timestamp if available. + // TODO(terelius): This could be improved. Instead of using the next start + // event, we could use the timestamp of the the last previous regular event. auto start_iter = start_log_events().begin(); auto stop_iter = stop_log_events().begin(); - while (start_iter != start_log_events().end()) { - int64_t start_us = start_iter->log_time_us(); + int64_t start_us = first_timestamp(); + int64_t next_start_us = std::numeric_limits::max(); + int64_t stop_us = std::numeric_limits::max(); + if (start_iter != start_log_events().end()) { + start_us = std::min(start_us, start_iter->log_time_us()); ++start_iter; - absl::optional next_start_us; if (start_iter != start_log_events().end()) - next_start_us.emplace(start_iter->log_time_us()); - if (stop_iter != stop_log_events().end() && - stop_iter->log_time_us() <= - next_start_us.value_or(std::numeric_limits::max())) { - int64_t stop_us = stop_iter->log_time_us(); - RTC_PARSE_CHECK_OR_RETURN_LE(start_us, stop_us); - log_segments_.emplace_back(start_us, stop_us); - ++stop_iter; - } else { - // We're missing an end event. Assume that it occurred just before the - // next start. - log_segments_.emplace_back(start_us, - next_start_us.value_or(last_timestamp())); - } + next_start_us = start_iter->log_time_us(); + } + if (stop_iter != stop_log_events().end()) { + stop_us = stop_iter->log_time_us(); + } + stop_us = std::min(stop_us, next_start_us); + if (stop_us == std::numeric_limits::max() && + last_timestamp() != std::numeric_limits::min()) { + stop_us = last_timestamp(); + } + RTC_PARSE_CHECK_OR_RETURN_LE(start_us, stop_us); + first_log_segment_ = LogSegment(start_us, stop_us); + + if (first_timestamp_ == std::numeric_limits::max() && + last_timestamp_ == std::numeric_limits::min()) { + first_timestamp_ = last_timestamp_ = 0; } return status; diff --git a/logging/rtc_event_log/rtc_event_log_parser.h b/logging/rtc_event_log/rtc_event_log_parser.h index 2165631fd1..8d3351e815 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.h +++ b/logging/rtc_event_log/rtc_event_log_parser.h @@ -11,6 +11,7 @@ #define LOGGING_RTC_EVENT_LOG_RTC_EVENT_LOG_PARSER_H_ #include +#include #include #include #include // no-presubmit-check TODO(webrtc:8982) @@ -613,7 +614,7 @@ class ParsedRtcEventLog { int64_t first_timestamp() const { return first_timestamp_; } int64_t last_timestamp() const { return last_timestamp_; } - const std::vector& log_segments() const { return log_segments_; } + const LogSegment& first_log_segment() const { return first_log_segment_; } std::vector GetPacketInfos(PacketDirection direction) const; std::vector GetIncomingPacketInfos() const { @@ -868,8 +869,8 @@ class ParsedRtcEventLog { int64_t first_timestamp_; int64_t last_timestamp_; - // Stores the start and end timestamp for each log segments. - std::vector log_segments_; + LogSegment first_log_segment_ = + LogSegment(0, std::numeric_limits::max()); // The extension maps are mutable to allow us to insert the default // configuration when parsing an RTP header for an unconfigured stream. diff --git a/logging/rtc_event_log/rtc_event_log_unittest.cc b/logging/rtc_event_log/rtc_event_log_unittest.cc index 59890066c5..e785d6160a 100644 --- a/logging/rtc_event_log/rtc_event_log_unittest.cc +++ b/logging/rtc_event_log/rtc_event_log_unittest.cc @@ -739,10 +739,10 @@ void RtcEventLogSession::ReadAndVerifyLog() { EXPECT_EQ(first_timestamp_ms_, parsed_log.first_timestamp() / 1000); EXPECT_EQ(last_timestamp_ms_, parsed_log.last_timestamp() / 1000); - ASSERT_EQ(parsed_log.log_segments().size(), 1u); - EXPECT_EQ(parsed_log.log_segments()[0].start_time_ms(), - start_time_us_ / 1000); - EXPECT_EQ(parsed_log.log_segments()[0].stop_time_ms(), stop_time_us_ / 1000); + EXPECT_EQ(parsed_log.first_log_segment().start_time_ms(), + std::min(start_time_us_ / 1000, first_timestamp_ms_)); + EXPECT_EQ(parsed_log.first_log_segment().stop_time_ms(), + stop_time_us_ / 1000); // Clean up temporary file - can be pretty slow. remove(temp_filename_.c_str()); diff --git a/rtc_tools/rtc_event_log_visualizer/alerts.cc b/rtc_tools/rtc_event_log_visualizer/alerts.cc index f2d9564795..86372de4cf 100644 --- a/rtc_tools/rtc_event_log_visualizer/alerts.cc +++ b/rtc_tools/rtc_event_log_visualizer/alerts.cc @@ -62,10 +62,7 @@ void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log, direction == kIncomingPacket ? TriageAlertType::kIncomingCaptureTimeJump : TriageAlertType::kOutgoingCaptureTimeJump; - const int64_t segment_end_us = - parsed_log.log_segments().empty() - ? std::numeric_limits::max() - : parsed_log.log_segments().front().stop_time_us(); + 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)) { @@ -133,10 +130,7 @@ void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log, ? TriageAlertType::kIncomingRtcpGap : TriageAlertType::kOutgoingRtcpGap; - const int64_t segment_end_us = - parsed_log.log_segments().empty() - ? std::numeric_limits::max() - : parsed_log.log_segments().front().stop_time_us(); + 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. @@ -202,10 +196,7 @@ void TriageHelper::AnalyzeLog(const ParsedRtcEventLog& parsed_log) { AnalyzeTransmissionGaps(parsed_log, kIncomingPacket); AnalyzeTransmissionGaps(parsed_log, kOutgoingPacket); - const int64_t segment_end_us = - parsed_log.log_segments().empty() - ? std::numeric_limits::max() - : parsed_log.log_segments().front().stop_time_us(); + const int64_t segment_end_us = parsed_log.first_log_segment().stop_time_us(); int64_t first_occurrence = parsed_log.last_timestamp(); constexpr double kMaxLossFraction = 0.05; diff --git a/rtc_tools/rtc_event_log_visualizer/analyzer.cc b/rtc_tools/rtc_event_log_visualizer/analyzer.cc index 9a9a4553f8..a0e441c36c 100644 --- a/rtc_tools/rtc_event_log_visualizer/analyzer.cc +++ b/rtc_tools/rtc_event_log_visualizer/analyzer.cc @@ -465,15 +465,21 @@ EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLog& log, config_.begin_time_ = config_.end_time_ = 0; } - RTC_LOG(LS_INFO) << "Found " << parsed_log_.log_segments().size() - << " (LOG_START, LOG_END) segments in log."; + RTC_LOG(LS_INFO) << "Log is " + << (parsed_log_.last_timestamp() - + parsed_log_.first_timestamp()) / + 1000000 + << " seconds long."; } 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."; + RTC_LOG(LS_INFO) << "Log is " + << (parsed_log_.last_timestamp() - + parsed_log_.first_timestamp()) / + 1000000 + << " seconds long."; } class BitrateObserver : public RemoteBitrateObserver { @@ -852,10 +858,7 @@ void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) { << packets.size() << " packets in the stream."; continue; } - int64_t segment_end_us = - parsed_log_.log_segments().empty() - ? std::numeric_limits::max() - : parsed_log_.log_segments().front().stop_time_us(); + int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us(); absl::optional estimated_frequency = EstimateRtpClockFrequency(packets, segment_end_us); if (!estimated_frequency) @@ -1586,10 +1589,7 @@ void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) { "pacer delay with less than 2 packets in the stream"; continue; } - int64_t segment_end_us = - parsed_log_.log_segments().empty() - ? std::numeric_limits::max() - : parsed_log_.log_segments().front().stop_time_us(); + int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us(); absl::optional estimated_frequency = EstimateRtpClockFrequency(packets, segment_end_us); if (!estimated_frequency) @@ -2050,11 +2050,7 @@ EventLogAnalyzer::NetEqStatsGetterMap EventLogAnalyzer::SimulateNetEq( output_events_it = parsed_log_.audio_playout_events().cbegin(); } - absl::optional end_time_ms = - parsed_log_.log_segments().empty() - ? absl::nullopt - : absl::optional( - parsed_log_.log_segments().front().stop_time_ms()); + int64_t end_time_ms = parsed_log_.first_log_segment().stop_time_ms(); neteq_stats[ssrc] = CreateNetEqTestAndRun( audio_packets, &output_events_it->second, end_time_ms,