Replace inconsistent log_segments() function in RTC event log parser

Bug: webrtc:11566
Change-Id: I739bbc29ae5423f3fedcc08e991e27fa0af840c5
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/176081
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Reviewed-by: Mirko Bonadei <mbonadei@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31371}
This commit is contained in:
Björn Terelius 2020-05-27 20:25:06 +02:00 committed by Commit Bot
parent 0ee4ee85dd
commit 0d1b28cf09
6 changed files with 59 additions and 59 deletions

View File

@ -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.

View File

@ -1076,6 +1076,7 @@ void ParsedRtcEventLog::Clear() {
first_timestamp_ = std::numeric_limits<int64_t>::max();
last_timestamp_ = std::numeric_limits<int64_t>::min();
first_log_segment_ = LogSegment(0, std::numeric_limits<int64_t>::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<int64_t>::max();
int64_t stop_us = std::numeric_limits<int64_t>::max();
if (start_iter != start_log_events().end()) {
start_us = std::min(start_us, start_iter->log_time_us());
++start_iter;
absl::optional<int64_t> 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<int64_t>::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<int64_t>::max() &&
last_timestamp() != std::numeric_limits<int64_t>::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<int64_t>::max() &&
last_timestamp_ == std::numeric_limits<int64_t>::min()) {
first_timestamp_ = last_timestamp_ = 0;
}
return status;

View File

@ -11,6 +11,7 @@
#define LOGGING_RTC_EVENT_LOG_RTC_EVENT_LOG_PARSER_H_
#include <iterator>
#include <limits>
#include <map>
#include <set>
#include <sstream> // 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<LogSegment>& log_segments() const { return log_segments_; }
const LogSegment& first_log_segment() const { return first_log_segment_; }
std::vector<LoggedPacketInfo> GetPacketInfos(PacketDirection direction) const;
std::vector<LoggedPacketInfo> 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<LogSegment> log_segments_;
LogSegment first_log_segment_ =
LogSegment(0, std::numeric_limits<int64_t>::max());
// The extension maps are mutable to allow us to insert the default
// configuration when parsing an RTP header for an unconfigured stream.

View File

@ -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());

View File

@ -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<int64_t>::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<int64_t>::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<int64_t>::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;

View File

@ -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<int64_t>::max()
: parsed_log_.log_segments().front().stop_time_us();
int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
absl::optional<uint32_t> 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<int64_t>::max()
: parsed_log_.log_segments().front().stop_time_us();
int64_t segment_end_us = parsed_log_.first_log_segment().stop_time_us();
absl::optional<uint32_t> 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<int64_t> end_time_ms =
parsed_log_.log_segments().empty()
? absl::nullopt
: absl::optional<int64_t>(
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,