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