From 4f3c4fcb1f26606af9e7ce0420d1fa8fbc95d82f Mon Sep 17 00:00:00 2001 From: Artem Titov Date: Fri, 28 Feb 2020 15:17:57 +0100 Subject: [PATCH] Temporary debug logging for SingleProcessEncodedImageDataInjector Bug: None Change-Id: Idb482c002ed41b9ad750109fd3497425003be11b Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/169448 Reviewed-by: Mirko Bonadei Commit-Queue: Artem Titov Cr-Commit-Position: refs/heads/master@{#30649} --- test/pc/e2e/BUILD.gn | 2 + ...gle_process_encoded_image_data_injector.cc | 74 ++++++++++++++++++- ...ngle_process_encoded_image_data_injector.h | 12 +++ 3 files changed, 86 insertions(+), 2 deletions(-) diff --git a/test/pc/e2e/BUILD.gn b/test/pc/e2e/BUILD.gn index 1e61ee0827..3855ad0141 100644 --- a/test/pc/e2e/BUILD.gn +++ b/test/pc/e2e/BUILD.gn @@ -98,8 +98,10 @@ rtc_library("single_process_encoded_image_data_injector") { deps = [ ":encoded_image_data_injector_api", "../../../api/video:encoded_image", + "../../../modules/rtp_rtcp:rtp_rtcp_format", "../../../rtc_base:checks", "../../../rtc_base:criticalsection", + "../../../rtc_base:logging", "//third_party/abseil-cpp/absl/memory", ] } diff --git a/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.cc b/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.cc index ec0d26b780..bb95fca171 100644 --- a/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.cc +++ b/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.cc @@ -10,12 +10,15 @@ #include "test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.h" +#include #include #include #include "absl/memory/memory.h" #include "api/video/encoded_image.h" +#include "modules/rtp_rtcp/source/byte_io.h" #include "rtc_base/checks.h" +#include "rtc_base/logging.h" namespace webrtc { namespace webrtc_pc_e2e { @@ -25,6 +28,13 @@ namespace { // used to store frame id and sub id. constexpr size_t kUsedBufferSize = 3; +std::string UInt64ToHex(uint64_t value) { + char buffer[50]; + snprintf(buffer, sizeof(buffer), "0x%016" PRIx64, value); + + return std::string(buffer); +} + } // namespace SingleProcessEncodedImageDataInjector::SingleProcessEncodedImageDataInjector() = @@ -56,6 +66,22 @@ EncodedImage SingleProcessEncodedImageDataInjector::InjectData( out.data()[insertion_pos] = id & 0x00ff; out.data()[insertion_pos + 1] = (id & 0xff00) >> 8; out.data()[insertion_pos + 2] = info.sub_id; + + // Debug logging start + RTC_CHECK_GE(source.size(), 8); + DebugLogEntry entry; + entry.side = LogSide::kSend; + entry.frame_id = id; + entry.size = source.size(); + entry.image_starting = ByteReader::ReadBigEndian(source.data()); + entry.image_ending = + ByteReader::ReadBigEndian(&source.data()[source.size() - 8]); + { + rtc::CritScope crit(&debug_lock_); + debug_logs.push_back(entry); + } + // Debug logging end + return out; } @@ -69,6 +95,17 @@ EncodedImageExtractionResult SingleProcessEncodedImageDataInjector::ExtractData( uint8_t* buffer = out.data(); size_t size = out.size(); + // Debug logging start + RTC_CHECK_GE(source.size(), 8); + DebugLogEntry entry; + entry.side = LogSide::kReceive; + entry.size = source.size(); + entry.image_starting = ByteReader::ReadBigEndian(source.data()); + entry.image_ending = + ByteReader::ReadBigEndian(&source.data()[source.size() - 8]); + bool is_debug_logged = false; + // Debug logging end + // |pos| is pointing to end of current encoded image. size_t pos = size - 1; absl::optional id = absl::nullopt; @@ -86,12 +123,45 @@ EncodedImageExtractionResult SingleProcessEncodedImageDataInjector::ExtractData( << "Different frames encoded into single encoded image: " << *id << " vs " << next_id; id = next_id; + + // Debug logging start + if (!is_debug_logged) { + entry.frame_id = next_id; + { + rtc::CritScope crit(&debug_lock_); + debug_logs.push_back(entry); + } + is_debug_logged = true; + } + // Debug logging end + ExtractionInfo info; { rtc::CritScope crit(&lock_); auto ext_vector_it = extraction_cache_.find(next_id); - RTC_CHECK(ext_vector_it != extraction_cache_.end()) - << "Unknown frame_id=" << next_id; + // We replace RTC_CHECK on if here to add some debug logging. + if (ext_vector_it == extraction_cache_.end()) { + { + rtc::CritScope crit(&debug_lock_); + RTC_LOG(INFO) << "##################################################"; + RTC_LOG(INFO) << "# SingleProcessEncodedImageDataInjector crashed! #"; + RTC_LOG(INFO) << "##################################################"; + for (const auto& entry : debug_logs) { + RTC_LOG(INFO) << "## SPEIDI: Frame: " << entry.frame_id + << "; Side: " + << (entry.side == LogSide::kSend ? "kSend" + : "kReceive") + << "; Size: " << entry.size + << "; EncodedImage starts with: " + << UInt64ToHex(entry.image_starting) + << "; EncodedImage ends with: " + << UInt64ToHex(entry.image_ending); + } + } + RTC_CHECK(false) << "Unknown frame_id=" << next_id; + } + // RTC_CHECK(ext_vector_it != extraction_cache_.end()) + // << "Unknown frame_id=" << next_id; auto info_it = ext_vector_it->second.infos.find(sub_id); RTC_CHECK(info_it != ext_vector_it->second.infos.end()) diff --git a/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.h b/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.h index 3787cc51aa..0e60279f1a 100644 --- a/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.h +++ b/test/pc/e2e/analyzer/video/single_process_encoded_image_data_injector.h @@ -77,6 +77,18 @@ class SingleProcessEncodedImageDataInjector : public EncodedImageDataInjector, std::map infos; }; + enum class LogSide { kSend, kReceive }; + + struct DebugLogEntry { + uint16_t frame_id; + LogSide side; + size_t size; + uint64_t image_starting; + uint64_t image_ending; + }; + rtc::CriticalSection debug_lock_; + std::vector debug_logs RTC_GUARDED_BY(debug_lock_); + rtc::CriticalSection lock_; // Stores a mapping from frame id to extraction info for spatial layers // for this frame id. There can be a lot of them, because if frame was