Group decoded frame events by SSRC when compressing RTC event log.

Correspondingly, change the parser so that it provides the frames
grouped by SSRC.

Also fix a small bug that made the audio playout test terminate
too early before verifying correct logging of all events.

Bug: webrtc:8802
Change-Id: I363ef120cf88fe99290998cbc14ab5dbf32e9607
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/181066
Reviewed-by: Artem Titov <titovartem@webrtc.org>
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31962}

logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc

@@ -698,7 +698,8 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
     std::vector<const RtcEventBweUpdateLossBased*> bwe_loss_based_updates;
     std::vector<const RtcEventDtlsTransportState*> dtls_transport_states;
     std::vector<const RtcEventDtlsWritableState*> dtls_writable_states;
-    std::vector<const RtcEventFrameDecoded*> frames_decoded;
+    std::map<uint32_t /* SSRC */, std::vector<const RtcEventFrameDecoded*>>
+        frames_decoded;
     std::vector<const RtcEventGenericAckReceived*> generic_acks_received;
     std::vector<const RtcEventGenericPacketReceived*> generic_packets_received;
     std::vector<const RtcEventGenericPacketSent*> generic_packets_sent;
@@ -884,8 +885,7 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
         case RtcEvent::Type::FrameDecoded: {
           auto* rtc_event =
               static_cast<const RtcEventFrameDecoded* const>(it->get());
-          // TODO(terelius):  Group by SSRC
+          frames_decoded[rtc_event->ssrc()].emplace_back(rtc_event);
-          frames_decoded.push_back(rtc_event);
           break;
         }
       }
@@ -901,7 +901,9 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
     EncodeBweUpdateLossBased(bwe_loss_based_updates, &event_stream);
     EncodeDtlsTransportState(dtls_transport_states, &event_stream);
     EncodeDtlsWritableState(dtls_writable_states, &event_stream);
-    EncodeFramesDecoded(frames_decoded, &event_stream);
+    for (const auto& kv : frames_decoded) {
+      EncodeFramesDecoded(kv.second, &event_stream);
+    }
     EncodeGenericAcksReceived(generic_acks_received, &event_stream);
     EncodeGenericPacketsReceived(generic_packets_received, &event_stream);
     EncodeGenericPacketsSent(generic_packets_sent, &event_stream);
@@ -1462,7 +1464,7 @@ void RtcEventLogEncoderNewFormat::EncodeRtpPacketIncoming(
 }
 
 void RtcEventLogEncoderNewFormat::EncodeFramesDecoded(
-    rtc::ArrayView<const RtcEventFrameDecoded*> batch,
+    rtc::ArrayView<const RtcEventFrameDecoded* const> batch,
     rtclog2::EventStream* event_stream) {
   if (batch.empty()) {
     return;

logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.h

@@ -95,8 +95,9 @@ class RtcEventLogEncoderNewFormat final : public RtcEventLogEncoder {
   void EncodeDtlsWritableState(
       rtc::ArrayView<const RtcEventDtlsWritableState*> batch,
       rtclog2::EventStream* event_stream);
-  void EncodeFramesDecoded(rtc::ArrayView<const RtcEventFrameDecoded*> batch,
+  void EncodeFramesDecoded(
-                           rtclog2::EventStream* event_stream);
+      rtc::ArrayView<const RtcEventFrameDecoded* const> batch,
+      rtclog2::EventStream* event_stream);
   void EncodeGenericAcksReceived(
       rtc::ArrayView<const RtcEventGenericAckReceived*> batch,
       rtclog2::EventStream* event_stream);

logging/rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc

@@ -631,12 +631,23 @@ TEST_P(RtcEventLogEncoderTest, RtcEventDtlsWritableState) {
 }
 
 TEST_P(RtcEventLogEncoderTest, RtcEventFrameDecoded) {
-  std::vector<std::unique_ptr<RtcEventFrameDecoded>> events(event_count_);
+  // SSRCs will be randomly assigned out of this small pool, significant only
+  // in that it also covers such edge cases as SSRC = 0 and SSRC = 0xffffffff.
+  // The pool is intentionally small, so as to produce collisions.
+  const std::vector<uint32_t> kSsrcPool = {0x00000000, 0x12345678, 0xabcdef01,
+                                           0xffffffff, 0x20171024, 0x19840730,
+                                           0x19831230};
+
+  std::map<uint32_t, std::vector<std::unique_ptr<RtcEventFrameDecoded>>>
+      original_events_by_ssrc;
   for (size_t i = 0; i < event_count_; ++i) {
-    events[i] = (i == 0 || !force_repeated_fields_)
+    const uint32_t ssrc = kSsrcPool[prng_.Rand(kSsrcPool.size() - 1)];
-                    ? gen_.NewFrameDecodedEvent()
+    std::unique_ptr<RtcEventFrameDecoded> event =
-                    : events[0]->Copy();
+        (original_events_by_ssrc[ssrc].empty() || !force_repeated_fields_)
-    history_.push_back(events[i]->Copy());
+            ? gen_.NewFrameDecodedEvent(ssrc)
+            : original_events_by_ssrc[ssrc][0]->Copy();
+    history_.push_back(event->Copy());
+    original_events_by_ssrc[ssrc].push_back(std::move(event));
   }
 
   const std::string encoded =
@@ -646,16 +657,31 @@ TEST_P(RtcEventLogEncoderTest, RtcEventFrameDecoded) {
     RTC_LOG(LS_ERROR) << status.message();
   ASSERT_TRUE(status.ok());
 
-  const auto& decoded_frames = parsed_log_.decoded_frames();
+  const auto& decoded_frames_by_ssrc = parsed_log_.decoded_frames();
   if (!new_encoding_) {
-    ASSERT_EQ(decoded_frames.size(), 0u);
+    ASSERT_EQ(decoded_frames_by_ssrc.size(), 0u);
     return;
   }
 
-  ASSERT_EQ(decoded_frames.size(), event_count_);
+  // Same number of distinct SSRCs.
+  ASSERT_EQ(decoded_frames_by_ssrc.size(), original_events_by_ssrc.size());
 
-  for (size_t i = 0; i < event_count_; ++i) {
+  for (const auto& original_event_it : original_events_by_ssrc) {
-    verifier_.VerifyLoggedFrameDecoded(*events[i], decoded_frames[i]);
+    const uint32_t ssrc = original_event_it.first;
+    const std::vector<std::unique_ptr<RtcEventFrameDecoded>>& original_frames =
+        original_event_it.second;
+
+    const auto& parsed_event_it = decoded_frames_by_ssrc.find(ssrc);
+    ASSERT_TRUE(parsed_event_it != decoded_frames_by_ssrc.end());
+    const std::vector<LoggedFrameDecoded>& parsed_frames =
+        parsed_event_it->second;
+
+    // Same number events for the SSRC under examination.
+    ASSERT_EQ(original_frames.size(), parsed_frames.size());
+
+    for (size_t i = 0; i < original_frames.size(); ++i) {
+      verifier_.VerifyLoggedFrameDecoded(*original_frames[i], parsed_frames[i]);
+    }
   }
 }
 

logging/rtc_event_log/rtc_event_log_parser.cc

@@ -1222,7 +1222,9 @@ ParsedRtcEventLog::ParseStatus ParsedRtcEventLog::ParseStream(
   StoreFirstAndLastTimestamp(bwe_probe_success_events());
   StoreFirstAndLastTimestamp(bwe_delay_updates());
   StoreFirstAndLastTimestamp(bwe_loss_updates());
-  StoreFirstAndLastTimestamp(decoded_frames());
+  for (const auto& frame_stream : decoded_frames()) {
+    StoreFirstAndLastTimestamp(frame_stream.second);
+  }
   StoreFirstAndLastTimestamp(dtls_transport_states());
   StoreFirstAndLastTimestamp(dtls_writable_states());
   StoreFirstAndLastTimestamp(ice_candidate_pair_configs());
@@ -2811,7 +2813,7 @@ ParsedRtcEventLog::ParseStatus ParsedRtcEventLog::StoreFrameDecodedEvents(
   RTC_PARSE_CHECK_OR_RETURN_LE(proto.qp(), 255);
   base_frame.qp = static_cast<uint8_t>(proto.qp());
 
-  decoded_frames_.push_back(base_frame);
+  decoded_frames_[base_frame.ssrc].push_back(base_frame);
 
   const size_t number_of_deltas =
       proto.has_number_of_deltas() ? proto.number_of_deltas() : 0u;
@@ -2892,7 +2894,7 @@ ParsedRtcEventLog::ParseStatus ParsedRtcEventLog::StoreFrameDecodedEvents(
                                  std::numeric_limits<uint8_t>::max());
     frame.qp = static_cast<uint8_t>(qp_values[i].value());
 
-    decoded_frames_.push_back(frame);
+    decoded_frames_[frame.ssrc].push_back(frame);
   }
   return ParseStatus::Success();
 }

logging/rtc_event_log/rtc_event_log_parser.h

@@ -612,7 +612,8 @@ class ParsedRtcEventLog {
   }
 
   // Media
-  const std::vector<LoggedFrameDecoded>& decoded_frames() const {
+  const std::map<uint32_t, std::vector<LoggedFrameDecoded>>& decoded_frames()
+      const {
     return decoded_frames_;
   }
 
@@ -855,7 +856,7 @@ class ParsedRtcEventLog {
   std::vector<LoggedDtlsTransportState> dtls_transport_states_;
   std::vector<LoggedDtlsWritableState> dtls_writable_states_;
 
-  std::vector<LoggedFrameDecoded> decoded_frames_;
+  std::map<uint32_t, std::vector<LoggedFrameDecoded>> decoded_frames_;
 
   std::vector<LoggedIceCandidatePairConfig> ice_candidate_pair_configs_;
   std::vector<LoggedIceCandidatePairEvent> ice_candidate_pair_events_;

logging/rtc_event_log/rtc_event_log_unittest.cc

@@ -166,7 +166,8 @@ class RtcEventLogSession
       dtls_transport_state_list_;
   std::vector<std::unique_ptr<RtcEventDtlsWritableState>>
       dtls_writable_state_list_;
-  std::vector<std::unique_ptr<RtcEventFrameDecoded>> frame_decoded_event_list_;
+  std::map<uint32_t, std::vector<std::unique_ptr<RtcEventFrameDecoded>>>
+      frame_decoded_event_map_;
   std::vector<std::unique_ptr<RtcEventGenericAckReceived>>
       generic_acks_received_;
   std::vector<std::unique_ptr<RtcEventGenericPacketReceived>>
@@ -447,9 +448,12 @@ void RtcEventLogSession::WriteLog(EventCounts count,
     selection -= count.dtls_writable_states;
 
     if (selection < count.frame_decoded_events) {
-      auto event = gen_.NewFrameDecodedEvent();
+      size_t stream = prng_.Rand(incoming_extensions_.size() - 1);
+      // This might be an audio SSRC, but that won't affect the parser.
+      uint32_t ssrc = incoming_extensions_[stream].first;
+      auto event = gen_.NewFrameDecodedEvent(ssrc);
       event_log->Log(event->Copy());
-      frame_decoded_event_list_.push_back(std::move(event));
+      frame_decoded_event_map_[ssrc].push_back(std::move(event));
       count.frame_decoded_events--;
       continue;
     }
@@ -588,7 +592,7 @@ void RtcEventLogSession::ReadAndVerifyLog() {
     const auto& parsed_audio_playout_stream = kv.second;
     const auto& audio_playout_stream = audio_playout_map_[ssrc];
     ASSERT_EQ(parsed_audio_playout_stream.size(), audio_playout_stream.size());
-    for (size_t i = 0; i < parsed_audio_playout_map.size(); i++) {
+    for (size_t i = 0; i < audio_playout_stream.size(); i++) {
       verifier_.VerifyLoggedAudioPlayoutEvent(*audio_playout_stream[i],
                                               parsed_audio_playout_stream[i]);
     }
@@ -656,12 +660,17 @@ void RtcEventLogSession::ReadAndVerifyLog() {
                                             parsed_dtls_writable_states[i]);
   }
 
-  auto& parsed_frame_decoded_events = parsed_log.decoded_frames();
+  const auto& parsed_frame_decoded_map = parsed_log.decoded_frames();
-  ASSERT_EQ(parsed_frame_decoded_events.size(),
+  ASSERT_EQ(parsed_frame_decoded_map.size(), frame_decoded_event_map_.size());
-            frame_decoded_event_list_.size());
+  for (const auto& kv : parsed_frame_decoded_map) {
-  for (size_t i = 0; i < parsed_frame_decoded_events.size(); i++) {
+    uint32_t ssrc = kv.first;
-    verifier_.VerifyLoggedFrameDecoded(*frame_decoded_event_list_[i],
+    const auto& parsed_decoded_frames = kv.second;
-                                       parsed_frame_decoded_events[i]);
+    const auto& decoded_frames = frame_decoded_event_map_[ssrc];
+    ASSERT_EQ(parsed_decoded_frames.size(), decoded_frames.size());
+    for (size_t i = 0; i < decoded_frames.size(); i++) {
+      verifier_.VerifyLoggedFrameDecoded(*decoded_frames[i],
+                                         parsed_decoded_frames[i]);
+    }
   }
 
   auto& parsed_ice_candidate_pair_configs =

logging/rtc_event_log/rtc_event_log_unittest_helper.cc

@@ -148,7 +148,8 @@ EventGenerator::NewDtlsWritableState() {
   return std::make_unique<RtcEventDtlsWritableState>(writable);
 }
 
-std::unique_ptr<RtcEventFrameDecoded> EventGenerator::NewFrameDecodedEvent() {
+std::unique_ptr<RtcEventFrameDecoded> EventGenerator::NewFrameDecodedEvent(
+    uint32_t ssrc) {
   constexpr int kMinRenderDelayMs = 1;
   constexpr int kMaxRenderDelayMs = 2000000;
   constexpr int kMaxWidth = 15360;
@@ -162,7 +163,6 @@ std::unique_ptr<RtcEventFrameDecoded> EventGenerator::NewFrameDecodedEvent() {
       kVideoCodecH264};
   const int64_t render_time_ms =
       rtc::TimeMillis() + prng_.Rand(kMinRenderDelayMs, kMaxRenderDelayMs);
-  const uint32_t ssrc = prng_.Rand<uint32_t>();
   const int width = prng_.Rand(kMinWidth, kMaxWidth);
   const int height = prng_.Rand(kMinHeight, kMaxHeight);
   const VideoCodecType codec = kCodecList[prng_.Rand(0, kNumCodecTypes - 1)];

logging/rtc_event_log/rtc_event_log_unittest_helper.h

@@ -72,7 +72,7 @@ class EventGenerator {
   std::unique_ptr<RtcEventBweUpdateLossBased> NewBweUpdateLossBased();
   std::unique_ptr<RtcEventDtlsTransportState> NewDtlsTransportState();
   std::unique_ptr<RtcEventDtlsWritableState> NewDtlsWritableState();
-  std::unique_ptr<RtcEventFrameDecoded> NewFrameDecodedEvent();
+  std::unique_ptr<RtcEventFrameDecoded> NewFrameDecodedEvent(uint32_t ssrc);
   std::unique_ptr<RtcEventGenericAckReceived> NewGenericAckReceived();
   std::unique_ptr<RtcEventGenericPacketReceived> NewGenericPacketReceived();
   std::unique_ptr<RtcEventGenericPacketSent> NewGenericPacketSent();