Store timestamp of first and last event in RTC event log parser.

This was previously only done for the legacy wire format.

Bug: webrtc:8111
Change-Id: I82767c8eafb35a50967c6ff3d0131c3981957c1f
Reviewed-on: https://webrtc-review.googlesource.com/c/112590
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Reviewed-by: Elad Alon <eladalon@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#25909}

logging/rtc_event_log/rtc_event_log_parser_new.cc

@@ -1002,6 +1002,39 @@ bool ParsedRtcEventLogNew::ParseStream(
                     &outgoing_remb_, &outgoing_nack_);
   }
 
+  // Store first and last timestamp events that might happen before the call is
+  // connected or after the call is disconnected. Typical examples are
+  // stream configurations and starting/stopping the log.
+  // TODO(terelius): Figure out if we actually need to find the first and last
+  // timestamp in the parser. It seems like this could be done by the caller.
+
+  first_timestamp_ = std::numeric_limits<int64_t>::max();
+  last_timestamp_ = std::numeric_limits<int64_t>::min();
+
+  StoreFirstAndLastTimestamp(alr_state_events());
+  for (const auto& audio_stream : audio_playout_events()) {
+    // Audio playout events are grouped by SSRC.
+    StoreFirstAndLastTimestamp(audio_stream.second);
+  }
+  StoreFirstAndLastTimestamp(audio_network_adaptation_events());
+  StoreFirstAndLastTimestamp(bwe_probe_cluster_created_events());
+  StoreFirstAndLastTimestamp(bwe_probe_failure_events());
+  StoreFirstAndLastTimestamp(bwe_probe_success_events());
+  StoreFirstAndLastTimestamp(bwe_delay_updates());
+  StoreFirstAndLastTimestamp(bwe_loss_updates());
+  StoreFirstAndLastTimestamp(dtls_transport_states());
+  StoreFirstAndLastTimestamp(dtls_writable_states());
+  StoreFirstAndLastTimestamp(ice_candidate_pair_configs());
+  StoreFirstAndLastTimestamp(ice_candidate_pair_events());
+  for (const auto& rtp_stream : incoming_rtp_packets_by_ssrc()) {
+    StoreFirstAndLastTimestamp(rtp_stream.incoming_packets);
+  }
+  for (const auto& rtp_stream : outgoing_rtp_packets_by_ssrc()) {
+    StoreFirstAndLastTimestamp(rtp_stream.outgoing_packets);
+  }
+  StoreFirstAndLastTimestamp(incoming_rtcp_packets());
+  StoreFirstAndLastTimestamp(outgoing_rtcp_packets());
+
   return success;
 }
 
@@ -1087,20 +1120,16 @@ bool ParsedRtcEventLogNew::ParseStreamInternal(
   return true;
 }
 
+template <typename T>
+void ParsedRtcEventLogNew::StoreFirstAndLastTimestamp(const std::vector<T>& v) {
+  if (v.empty())
+    return;
+  first_timestamp_ = std::min(first_timestamp_, v.front().log_time_us());
+  last_timestamp_ = std::max(last_timestamp_, v.back().log_time_us());
+}
+
 void ParsedRtcEventLogNew::StoreParsedLegacyEvent(const rtclog::Event& event) {
   RTC_CHECK(event.has_type());
-  if (event.type() != rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT &&
-      event.type() != rtclog::Event::VIDEO_SENDER_CONFIG_EVENT &&
-      event.type() != rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT &&
-      event.type() != rtclog::Event::AUDIO_SENDER_CONFIG_EVENT &&
-      event.type() != rtclog::Event::LOG_START &&
-      event.type() != rtclog::Event::LOG_END) {
-    RTC_CHECK(event.has_timestamp_us());
-    int64_t timestamp = event.timestamp_us();
-    first_timestamp_ = std::min(first_timestamp_, timestamp);
-    last_timestamp_ = std::max(last_timestamp_, timestamp);
-  }
-
   switch (event.type()) {
     case rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT: {
       rtclog::StreamConfig config = GetVideoReceiveConfig(event);
@@ -2271,7 +2300,7 @@ void ParsedRtcEventLogNew::StoreAudioNetworkAdaptationEvent(
   // were shifted down by one, but in the base event, they were not.
   // We likewise shift the base event down by one, to get the same base as
   // encoding had, but then shift all of the values (except the base) back up
-  //  to their original value.
+  // to their original value.
   absl::optional<uint64_t> shifted_base_num_channels;
   if (proto.has_num_channels()) {
     shifted_base_num_channels =

logging/rtc_event_log/rtc_event_log_parser_new.h

@@ -748,6 +748,10 @@ class ParsedRtcEventLogNew {
     return stop_log_events_;
   }
 
+  const std::vector<LoggedAlrStateEvent>& alr_state_events() const {
+    return alr_state_events_;
+  }
+
   // Audio
   const std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>&
   audio_playout_events() const {
@@ -783,19 +787,15 @@ class ParsedRtcEventLogNew {
     return bwe_loss_updates_;
   }
 
-  const std::vector<LoggedDtlsWritableState>& dtls_writable_states() const {
-    return dtls_writable_states_;
-  }
-
-  const std::vector<LoggedAlrStateEvent>& alr_state_events() const {
-    return alr_state_events_;
-  }
-
   // DTLS
   const std::vector<LoggedDtlsTransportState>& dtls_transport_states() const {
     return dtls_transport_states_;
   }
 
+  const std::vector<LoggedDtlsWritableState>& dtls_writable_states() const {
+    return dtls_writable_states_;
+  }
+
   // ICE events
   const std::vector<LoggedIceCandidatePairConfig>& ice_candidate_pair_configs()
       const {
@@ -889,6 +889,9 @@ class ParsedRtcEventLogNew {
 
   void StoreParsedLegacyEvent(const rtclog::Event& event);
 
+  template <typename T>
+  void StoreFirstAndLastTimestamp(const std::vector<T>& v);
+
   // Reads the arrival timestamp (in microseconds) from a rtclog::Event.
   int64_t GetTimestamp(const rtclog::Event& event) const;
 
@@ -954,19 +957,19 @@ class ParsedRtcEventLogNew {
   void StoreOutgoingRtpPackets(const rtclog2::OutgoingRtpPackets& proto);
   void StoreIncomingRtcpPackets(const rtclog2::IncomingRtcpPackets& proto);
   void StoreOutgoingRtcpPackets(const rtclog2::OutgoingRtcpPackets& proto);
-  void StoreAudioPlayoutEvent(const rtclog2::AudioPlayoutEvents& proto);
   void StoreStartEvent(const rtclog2::BeginLogEvent& proto);
   void StoreStopEvent(const rtclog2::EndLogEvent& proto);
-  void StoreBweLossBasedUpdate(const rtclog2::LossBasedBweUpdates& proto);
+  void StoreAlrStateEvent(const rtclog2::AlrState& proto);
-  void StoreBweDelayBasedUpdate(const rtclog2::DelayBasedBweUpdates& proto);
-  void StoreDtlsWritableState(const rtclog2::DtlsWritableState& proto);
   void StoreAudioNetworkAdaptationEvent(
       const rtclog2::AudioNetworkAdaptations& proto);
+  void StoreAudioPlayoutEvent(const rtclog2::AudioPlayoutEvents& proto);
+  void StoreBweLossBasedUpdate(const rtclog2::LossBasedBweUpdates& proto);
+  void StoreBweDelayBasedUpdate(const rtclog2::DelayBasedBweUpdates& proto);
   void StoreBweProbeClusterCreated(const rtclog2::BweProbeCluster& proto);
   void StoreBweProbeSuccessEvent(const rtclog2::BweProbeResultSuccess& proto);
   void StoreBweProbeFailureEvent(const rtclog2::BweProbeResultFailure& proto);
-  void StoreAlrStateEvent(const rtclog2::AlrState& proto);
   void StoreDtlsTransportState(const rtclog2::DtlsTransportStateEvent& proto);
+  void StoreDtlsWritableState(const rtclog2::DtlsWritableState& proto);
   void StoreIceCandidatePairConfig(
       const rtclog2::IceCandidatePairConfig& proto);
   void StoreIceCandidateEvent(const rtclog2::IceCandidatePairEvent& proto);
@@ -1044,6 +1047,8 @@ class ParsedRtcEventLogNew {
   std::vector<LoggedStartEvent> start_log_events_;
   std::vector<LoggedStopEvent> stop_log_events_;
 
+  std::vector<LoggedAlrStateEvent> alr_state_events_;
+
   std::map<uint32_t, std::vector<LoggedAudioPlayoutEvent>>
       audio_playout_events_;
 
@@ -1057,17 +1062,12 @@ class ParsedRtcEventLogNew {
   std::vector<LoggedBweProbeSuccessEvent> bwe_probe_success_events_;
 
   std::vector<LoggedBweDelayBasedUpdate> bwe_delay_updates_;
-
-  // A list of all updates from the send-side loss-based bandwidth estimator.
   std::vector<LoggedBweLossBasedUpdate> bwe_loss_updates_;
 
   std::vector<LoggedDtlsTransportState> dtls_transport_states_;
   std::vector<LoggedDtlsWritableState> dtls_writable_states_;
 
-  std::vector<LoggedAlrStateEvent> alr_state_events_;
-
   std::vector<LoggedIceCandidatePairConfig> ice_candidate_pair_configs_;
-
   std::vector<LoggedIceCandidatePairEvent> ice_candidate_pair_events_;
 
   std::vector<LoggedAudioRecvConfig> audio_recv_configs_;

logging/rtc_event_log/rtc_event_log_unittest.cc

@@ -9,6 +9,7 @@
  */
 
 #include <algorithm>
+#include <limits>
 #include <map>
 #include <memory>
 #include <string>
@@ -181,6 +182,9 @@ class RtcEventLogSession
   int64_t utc_start_time_us_;
   int64_t stop_time_us_;
 
+  int64_t first_timestamp_ms_ = std::numeric_limits<int64_t>::max();
+  int64_t last_timestamp_ms_ = std::numeric_limits<int64_t>::min();
+
   const uint64_t seed_;
   Random prng_;
   const int64_t output_period_ms_;
@@ -325,6 +329,8 @@ void RtcEventLogSession::WriteLog(EventCounts count,
 
     clock_.AdvanceTimeMicros(prng_.Rand(20) * 1000);
     size_t selection = prng_.Rand(remaining_events - 1);
+    first_timestamp_ms_ = std::min(first_timestamp_ms_, rtc::TimeMillis());
+    last_timestamp_ms_ = std::max(last_timestamp_ms_, rtc::TimeMillis());
 
     if (selection < count.alr_states) {
       auto event = gen_.NewAlrState();
@@ -656,6 +662,9 @@ void RtcEventLogSession::ReadAndVerifyLog() {
                                           parsed_video_send_configs[i]);
   }
 
+  EXPECT_EQ(first_timestamp_ms_, parsed_log.first_timestamp() / 1000);
+  EXPECT_EQ(last_timestamp_ms_, parsed_log.last_timestamp() / 1000);
+
   // Clean up temporary file - can be pretty slow.
   remove(temp_filename_.c_str());
 }