From bcdfc8975ea28f256f777d841e25f2e749090d96 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn=20Terelius?= Date: Wed, 19 Aug 2020 10:08:48 +0200 Subject: [PATCH] Group decoded frame events by SSRC when compressing RTC event log. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Commit-Queue: Björn Terelius Cr-Commit-Position: refs/heads/master@{#31962} --- .../rtc_event_log_encoder_new_format.cc | 12 +++-- .../rtc_event_log_encoder_new_format.h | 5 +- .../encoder/rtc_event_log_encoder_unittest.cc | 46 +++++++++++++++---- logging/rtc_event_log/rtc_event_log_parser.cc | 8 ++-- logging/rtc_event_log/rtc_event_log_parser.h | 5 +- .../rtc_event_log/rtc_event_log_unittest.cc | 29 ++++++++---- .../rtc_event_log_unittest_helper.cc | 4 +- .../rtc_event_log_unittest_helper.h | 2 +- 8 files changed, 76 insertions(+), 35 deletions(-) diff --git a/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc b/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc index 3cfd7a0a88..a2f52ac0a2 100644 --- a/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc +++ b/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc @@ -698,7 +698,8 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch( std::vector bwe_loss_based_updates; std::vector dtls_transport_states; std::vector dtls_writable_states; - std::vector frames_decoded; + std::map> + frames_decoded; std::vector generic_acks_received; std::vector generic_packets_received; std::vector generic_packets_sent; @@ -884,8 +885,7 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch( case RtcEvent::Type::FrameDecoded: { auto* rtc_event = static_cast(it->get()); - // TODO(terelius): Group by SSRC - frames_decoded.push_back(rtc_event); + frames_decoded[rtc_event->ssrc()].emplace_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 batch, + rtc::ArrayView batch, rtclog2::EventStream* event_stream) { if (batch.empty()) { return; diff --git a/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.h b/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.h index fdbe8fe854..6af34bc6cd 100644 --- a/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.h +++ b/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 batch, rtclog2::EventStream* event_stream); - void EncodeFramesDecoded(rtc::ArrayView batch, - rtclog2::EventStream* event_stream); + void EncodeFramesDecoded( + rtc::ArrayView batch, + rtclog2::EventStream* event_stream); void EncodeGenericAcksReceived( rtc::ArrayView batch, rtclog2::EventStream* event_stream); 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 c7b348e54a..ceee60b9eb 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 @@ -631,12 +631,23 @@ TEST_P(RtcEventLogEncoderTest, RtcEventDtlsWritableState) { } TEST_P(RtcEventLogEncoderTest, RtcEventFrameDecoded) { - std::vector> 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 kSsrcPool = {0x00000000, 0x12345678, 0xabcdef01, + 0xffffffff, 0x20171024, 0x19840730, + 0x19831230}; + + std::map>> + original_events_by_ssrc; for (size_t i = 0; i < event_count_; ++i) { - events[i] = (i == 0 || !force_repeated_fields_) - ? gen_.NewFrameDecodedEvent() - : events[0]->Copy(); - history_.push_back(events[i]->Copy()); + const uint32_t ssrc = kSsrcPool[prng_.Rand(kSsrcPool.size() - 1)]; + std::unique_ptr event = + (original_events_by_ssrc[ssrc].empty() || !force_repeated_fields_) + ? 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) { - verifier_.VerifyLoggedFrameDecoded(*events[i], decoded_frames[i]); + for (const auto& original_event_it : original_events_by_ssrc) { + const uint32_t ssrc = original_event_it.first; + const std::vector>& 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& 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]); + } } } diff --git a/logging/rtc_event_log/rtc_event_log_parser.cc b/logging/rtc_event_log/rtc_event_log_parser.cc index 4ab4332843..acd6f88e3e 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.cc +++ b/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(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::max()); frame.qp = static_cast(qp_values[i].value()); - decoded_frames_.push_back(frame); + decoded_frames_[frame.ssrc].push_back(frame); } return ParseStatus::Success(); } diff --git a/logging/rtc_event_log/rtc_event_log_parser.h b/logging/rtc_event_log/rtc_event_log_parser.h index 542f1cc6e7..712510b2a4 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.h +++ b/logging/rtc_event_log/rtc_event_log_parser.h @@ -612,7 +612,8 @@ class ParsedRtcEventLog { } // Media - const std::vector& decoded_frames() const { + const std::map>& decoded_frames() + const { return decoded_frames_; } @@ -855,7 +856,7 @@ class ParsedRtcEventLog { std::vector dtls_transport_states_; std::vector dtls_writable_states_; - std::vector decoded_frames_; + std::map> decoded_frames_; std::vector ice_candidate_pair_configs_; std::vector ice_candidate_pair_events_; diff --git a/logging/rtc_event_log/rtc_event_log_unittest.cc b/logging/rtc_event_log/rtc_event_log_unittest.cc index 5d5f450c15..b6fa1db539 100644 --- a/logging/rtc_event_log/rtc_event_log_unittest.cc +++ b/logging/rtc_event_log/rtc_event_log_unittest.cc @@ -166,7 +166,8 @@ class RtcEventLogSession dtls_transport_state_list_; std::vector> dtls_writable_state_list_; - std::vector> frame_decoded_event_list_; + std::map>> + frame_decoded_event_map_; std::vector> generic_acks_received_; std::vector> @@ -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(); - ASSERT_EQ(parsed_frame_decoded_events.size(), - frame_decoded_event_list_.size()); - for (size_t i = 0; i < parsed_frame_decoded_events.size(); i++) { - verifier_.VerifyLoggedFrameDecoded(*frame_decoded_event_list_[i], - parsed_frame_decoded_events[i]); + const auto& parsed_frame_decoded_map = parsed_log.decoded_frames(); + ASSERT_EQ(parsed_frame_decoded_map.size(), frame_decoded_event_map_.size()); + for (const auto& kv : parsed_frame_decoded_map) { + uint32_t ssrc = kv.first; + const auto& parsed_decoded_frames = kv.second; + 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 = diff --git a/logging/rtc_event_log/rtc_event_log_unittest_helper.cc b/logging/rtc_event_log/rtc_event_log_unittest_helper.cc index 905ac449f8..1c13cc6393 100644 --- a/logging/rtc_event_log/rtc_event_log_unittest_helper.cc +++ b/logging/rtc_event_log/rtc_event_log_unittest_helper.cc @@ -148,7 +148,8 @@ EventGenerator::NewDtlsWritableState() { return std::make_unique(writable); } -std::unique_ptr EventGenerator::NewFrameDecodedEvent() { +std::unique_ptr EventGenerator::NewFrameDecodedEvent( + uint32_t ssrc) { constexpr int kMinRenderDelayMs = 1; constexpr int kMaxRenderDelayMs = 2000000; constexpr int kMaxWidth = 15360; @@ -162,7 +163,6 @@ std::unique_ptr EventGenerator::NewFrameDecodedEvent() { kVideoCodecH264}; const int64_t render_time_ms = rtc::TimeMillis() + prng_.Rand(kMinRenderDelayMs, kMaxRenderDelayMs); - const uint32_t ssrc = prng_.Rand(); const int width = prng_.Rand(kMinWidth, kMaxWidth); const int height = prng_.Rand(kMinHeight, kMaxHeight); const VideoCodecType codec = kCodecList[prng_.Rand(0, kNumCodecTypes - 1)]; diff --git a/logging/rtc_event_log/rtc_event_log_unittest_helper.h b/logging/rtc_event_log/rtc_event_log_unittest_helper.h index b289737ddb..bf9fb573c1 100644 --- a/logging/rtc_event_log/rtc_event_log_unittest_helper.h +++ b/logging/rtc_event_log/rtc_event_log_unittest_helper.h @@ -72,7 +72,7 @@ class EventGenerator { std::unique_ptr NewBweUpdateLossBased(); std::unique_ptr NewDtlsTransportState(); std::unique_ptr NewDtlsWritableState(); - std::unique_ptr NewFrameDecodedEvent(); + std::unique_ptr NewFrameDecodedEvent(uint32_t ssrc); std::unique_ptr NewGenericAckReceived(); std::unique_ptr NewGenericPacketReceived(); std::unique_ptr NewGenericPacketSent();