From 1adce14c87f8316b5c3f4ee16b8f573c8bf14761 Mon Sep 17 00:00:00 2001 From: terelius Date: Fri, 16 Oct 2015 08:51:08 -0700 Subject: [PATCH] Old config events are no longer removed from RtcEventLog. Time to keep old events in buffer is now changeable at runtime. Added unit test for removing old events from buffer. Review URL: https://codereview.webrtc.org/1303713002 Cr-Commit-Position: refs/heads/master@{#10302} --- webrtc/call/rtc_event_log.cc | 73 +++++++++++++----- webrtc/call/rtc_event_log.h | 4 + webrtc/call/rtc_event_log_unittest.cc | 104 +++++++++++++++++++++++++- 3 files changed, 157 insertions(+), 24 deletions(-) diff --git a/webrtc/call/rtc_event_log.cc b/webrtc/call/rtc_event_log.cc index 6a159123fd..dd7a3b661b 100644 --- a/webrtc/call/rtc_event_log.cc +++ b/webrtc/call/rtc_event_log.cc @@ -11,6 +11,7 @@ #include "webrtc/call/rtc_event_log.h" #include +#include #include "webrtc/base/checks.h" #include "webrtc/base/criticalsection.h" @@ -36,6 +37,7 @@ namespace webrtc { // No-op implementation if flag is not set. class RtcEventLogImpl final : public RtcEventLog { public: + void SetBufferDuration(int64_t buffer_duration_us) override {} void StartLogging(const std::string& file_name, int duration_ms) override {} bool StartLogging(rtc::PlatformFile log_file) override { return false; } void StopLogging(void) override {} @@ -58,6 +60,9 @@ class RtcEventLogImpl final : public RtcEventLog { class RtcEventLogImpl final : public RtcEventLog { public: + RtcEventLogImpl(); + + void SetBufferDuration(int64_t buffer_duration_us) override; void StartLogging(const std::string& file_name, int duration_ms) override; bool StartLogging(rtc::PlatformFile log_file) override; void StopLogging() override; @@ -91,10 +96,6 @@ class RtcEventLogImpl final : public RtcEventLog { void AddRecentEvent(const rtclog::Event& event) EXCLUSIVE_LOCKS_REQUIRED(crit_); - // Amount of time in microseconds to record log events, before starting the - // actual log. - const int recent_log_duration_us = 10000000; - rtc::CriticalSection crit_; rtc::scoped_ptr file_ GUARDED_BY(crit_) = rtc::scoped_ptr(FileWrapper::Create()); @@ -102,10 +103,14 @@ class RtcEventLogImpl final : public RtcEventLog { rtc::kInvalidPlatformFileValue; rtclog::EventStream stream_ GUARDED_BY(crit_); std::deque recent_log_events_ GUARDED_BY(crit_); - bool currently_logging_ GUARDED_BY(crit_) = false; - int64_t start_time_us_ GUARDED_BY(crit_) = 0; - int64_t duration_us_ GUARDED_BY(crit_) = 0; - const Clock* const clock_ = Clock::GetRealTimeClock(); + std::vector config_events_ GUARDED_BY(crit_); + + // Microseconds to record log events, before starting the actual log. + int64_t buffer_duration_us_ GUARDED_BY(crit_); + bool currently_logging_ GUARDED_BY(crit_); + int64_t start_time_us_ GUARDED_BY(crit_); + int64_t duration_us_ GUARDED_BY(crit_); + const Clock* const clock_; }; namespace { @@ -148,7 +153,31 @@ rtclog::MediaType ConvertMediaType(MediaType media_type) { } // namespace +namespace { +bool IsConfigEvent(const rtclog::Event& event) { + rtclog::Event_EventType event_type = event.type(); + return 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; +} +} // namespace + // RtcEventLogImpl member functions. +RtcEventLogImpl::RtcEventLogImpl() + : file_(FileWrapper::Create()), + stream_(), + buffer_duration_us_(10000000), + currently_logging_(false), + start_time_us_(0), + duration_us_(0), + clock_(Clock::GetRealTimeClock()) { +} + +void RtcEventLogImpl::SetBufferDuration(int64_t buffer_duration_us) { + rtc::CritScope lock(&crit_); + buffer_duration_us_ = buffer_duration_us; +} void RtcEventLogImpl::StartLogging(const std::string& file_name, int duration_ms) { @@ -192,9 +221,18 @@ bool RtcEventLogImpl::StartLogging(rtc::PlatformFile log_file) { void RtcEventLogImpl::StartLoggingLocked() { currently_logging_ = true; - // Write all the recent events to the log file, ignoring any old events. + + // Write all old configuration events to the log file. + for (auto& event : config_events_) { + StoreToFile(&event); + } + // Write all recent configuration events to the log file, and + // write all other recent events to the log file, ignoring any old events. for (auto& event : recent_log_events_) { - if (event.timestamp_us() >= start_time_us_ - recent_log_duration_us) { + if (IsConfigEvent(event)) { + StoreToFile(&event); + config_events_.push_back(event); + } else if (event.timestamp_us() >= start_time_us_ - buffer_duration_us_) { StoreToFile(&event); } } @@ -250,10 +288,6 @@ void RtcEventLogImpl::LogVideoReceiveStreamConfig( decoder->set_name(d.payload_name); decoder->set_payload_type(d.payload_type); } - // TODO(terelius): We should use a separate event queue for config events. - // The current approach of storing the configuration together with the - // RTP events causes the configuration information to be removed 10s - // after the ReceiveStream is created. HandleEvent(&event); } @@ -289,11 +323,6 @@ void RtcEventLogImpl::LogVideoSendStreamConfig( rtclog::EncoderConfig* encoder = sender_config->mutable_encoder(); encoder->set_name(config.encoder_settings.payload_name); encoder->set_payload_type(config.encoder_settings.payload_type); - - // TODO(terelius): We should use a separate event queue for config events. - // The current approach of storing the configuration together with the - // RTP events causes the configuration information to be removed 10s - // after the ReceiveStream is created. HandleEvent(&event); } @@ -404,7 +433,10 @@ void RtcEventLogImpl::StoreToFile(rtclog::Event* event) { void RtcEventLogImpl::AddRecentEvent(const rtclog::Event& event) { recent_log_events_.push_back(event); while (recent_log_events_.front().timestamp_us() < - event.timestamp_us() - recent_log_duration_us) { + event.timestamp_us() - buffer_duration_us_) { + if (IsConfigEvent(recent_log_events_.front())) { + config_events_.push_back(recent_log_events_.front()); + } recent_log_events_.pop_front(); } } @@ -431,4 +463,5 @@ bool RtcEventLog::ParseRtcEventLog(const std::string& file_name, rtc::scoped_ptr RtcEventLog::Create() { return rtc::scoped_ptr(new RtcEventLogImpl()); } + } // namespace webrtc diff --git a/webrtc/call/rtc_event_log.h b/webrtc/call/rtc_event_log.h index 02bbdc6001..85d7525752 100644 --- a/webrtc/call/rtc_event_log.h +++ b/webrtc/call/rtc_event_log.h @@ -36,6 +36,10 @@ class RtcEventLog { static rtc::scoped_ptr Create(); + // Sets the time that events are stored in the internal event buffer + // before the user calls StartLogging. The default is 10 000 000 us = 10 s + virtual void SetBufferDuration(int64_t buffer_duration_us) = 0; + // Starts logging for the specified duration to the specified file. // The logging will stop automatically after the specified duration. // If the file already exists it will be overwritten. diff --git a/webrtc/call/rtc_event_log_unittest.cc b/webrtc/call/rtc_event_log_unittest.cc index 536b997227..cae2a202e0 100644 --- a/webrtc/call/rtc_event_log_unittest.cc +++ b/webrtc/call/rtc_event_log_unittest.cc @@ -18,6 +18,7 @@ #include "webrtc/base/buffer.h" #include "webrtc/base/checks.h" #include "webrtc/base/scoped_ptr.h" +#include "webrtc/base/thread.h" #include "webrtc/call.h" #include "webrtc/call/rtc_event_log.h" #include "webrtc/modules/rtp_rtcp/source/rtp_sender.h" @@ -392,14 +393,14 @@ void GenerateVideoSendConfig(uint32_t extensions_bitvector, } } -// Test for the RtcEventLog class. Dumps some RTP packets to disk, then reads -// them back to see if they match. +// Test for the RtcEventLog class. Dumps some RTP packets and other events +// to disk, then reads them back to see if they match. void LogSessionAndReadBack(size_t rtp_count, size_t rtcp_count, size_t playout_count, uint32_t extensions_bitvector, uint32_t csrcs_count, - unsigned random_seed) { + unsigned int random_seed) { ASSERT_LE(rtcp_count, rtp_count); ASSERT_LE(playout_count, rtp_count); std::vector rtp_packets; @@ -476,7 +477,9 @@ void LogSessionAndReadBack(size_t rtp_count, ASSERT_TRUE(RtcEventLog::ParseRtcEventLog(temp_filename, &parsed_stream)); - // Verify the result. + // Verify that what we read back from the event log is the same as + // what we wrote down. For RTCP we log the full packets, but for + // RTP we should only log the header. const int event_count = config_count + playout_count + rtcp_count + rtp_count + 1; EXPECT_EQ(event_count, parsed_stream.stream_size()); @@ -546,6 +549,99 @@ TEST(RtcEventLogTest, LogSessionAndReadBack) { } } +// Tests that the event queue works correctly, i.e. drops old RTP, RTCP and +// debug events, but keeps config events even if they are older than the limit. +void DropOldEvents(uint32_t extensions_bitvector, + uint32_t csrcs_count, + unsigned int random_seed) { + rtc::Buffer old_rtp_packet; + rtc::Buffer recent_rtp_packet; + rtc::Buffer old_rtcp_packet; + rtc::Buffer recent_rtcp_packet; + + VideoReceiveStream::Config receiver_config(nullptr); + VideoSendStream::Config sender_config(nullptr); + + srand(random_seed); + + // Create two RTP packets containing random data. + size_t packet_size = 1000 + rand() % 64; + old_rtp_packet.SetSize(packet_size); + GenerateRtpPacket(extensions_bitvector, csrcs_count, old_rtp_packet.data(), + packet_size); + packet_size = 1000 + rand() % 64; + recent_rtp_packet.SetSize(packet_size); + size_t recent_header_size = GenerateRtpPacket( + extensions_bitvector, csrcs_count, recent_rtp_packet.data(), packet_size); + + // Create two RTCP packets containing random data. + packet_size = 1000 + rand() % 64; + old_rtcp_packet.SetSize(packet_size); + GenerateRtcpPacket(old_rtcp_packet.data(), packet_size); + packet_size = 1000 + rand() % 64; + recent_rtcp_packet.SetSize(packet_size); + GenerateRtcpPacket(recent_rtcp_packet.data(), packet_size); + + // Create configurations for the video streams. + GenerateVideoReceiveConfig(extensions_bitvector, &receiver_config); + GenerateVideoSendConfig(extensions_bitvector, &sender_config); + + // Find the name of the current test, in order to use it as a temporary + // filename. + auto test_info = ::testing::UnitTest::GetInstance()->current_test_info(); + const std::string temp_filename = + test::OutputPath() + test_info->test_case_name() + test_info->name(); + + // The log file will be flushed to disk when the log_dumper goes out of scope. + { + rtc::scoped_ptr log_dumper(RtcEventLog::Create()); + // Reduce the time old events are stored to 50 ms. + log_dumper->SetBufferDuration(50000); + log_dumper->LogVideoReceiveStreamConfig(receiver_config); + log_dumper->LogVideoSendStreamConfig(sender_config); + log_dumper->LogRtpHeader(false, MediaType::AUDIO, old_rtp_packet.data(), + old_rtp_packet.size()); + log_dumper->LogRtcpPacket(true, MediaType::AUDIO, old_rtcp_packet.data(), + old_rtcp_packet.size()); + // Sleep 55 ms to let old events be removed from the queue. + rtc::Thread::SleepMs(55); + log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->LogRtpHeader(true, MediaType::VIDEO, recent_rtp_packet.data(), + recent_rtp_packet.size()); + log_dumper->LogRtcpPacket(false, MediaType::VIDEO, + recent_rtcp_packet.data(), + recent_rtcp_packet.size()); + } + + // Read the generated file from disk. + rtclog::EventStream parsed_stream; + ASSERT_TRUE(RtcEventLog::ParseRtcEventLog(temp_filename, &parsed_stream)); + + // Verify that what we read back from the event log is the same as + // what we wrote. Old RTP and RTCP events should have been discarded, + // but old configuration events should still be available. + EXPECT_EQ(5, parsed_stream.stream_size()); + VerifyReceiveStreamConfig(parsed_stream.stream(0), receiver_config); + VerifySendStreamConfig(parsed_stream.stream(1), sender_config); + VerifyLogStartEvent(parsed_stream.stream(2)); + VerifyRtpEvent(parsed_stream.stream(3), true, MediaType::VIDEO, + recent_rtp_packet.data(), recent_header_size, + recent_rtp_packet.size()); + VerifyRtcpEvent(parsed_stream.stream(4), false, MediaType::VIDEO, + recent_rtcp_packet.data(), recent_rtcp_packet.size()); + + // Clean up temporary file - can be pretty slow. + remove(temp_filename.c_str()); +} + +TEST(RtcEventLogTest, DropOldEvents) { + // Enable all header extensions + uint32_t extensions = (1u << kNumExtensions) - 1; + uint32_t csrcs_count = 2; + DropOldEvents(extensions, csrcs_count, 141421356); + DropOldEvents(extensions, csrcs_count, 173205080); +} + } // namespace webrtc #endif // ENABLE_RTC_EVENT_LOG