From de939432dc1e465b7b8de9787f4ac7df398f5cea Mon Sep 17 00:00:00 2001 From: Bjorn Terelius Date: Mon, 20 Nov 2017 17:38:14 +0100 Subject: [PATCH] Revert "Revert "Encode log events periodically instead of for every event."" MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This reverts commit 33c5c7f5e4f018a5103770021328fc530d451d75. Reason for revert: Fix broken API change. TBR=sprang@webrtc.org,solenberg@webrtc.org TBRing because only pc/ and api/ have changed since last LGTMed version. Original change's description: > Revert "Encode log events periodically instead of for every event." > > This reverts commit b154c27e72fddb6c0d7cac69a9c68fff22154519. > > Reason for revert: Broke the internal project. > > Original change's description: > > Encode log events periodically instead of for every event. > > > > Updated unit test to take output_period and random seed as parameters. > > Updated the peerconnection interface to allow passing in an output_period. > > > > This is in preparation of some upcoming CLs that will change the format > > to store batches of delta-encoded values. > > > > > > Bug: webrtc:8111 > > Change-Id: Id5d9844dfad8d8edad346cd7cbebc7eadaaa5416 > > Reviewed-on: https://webrtc-review.googlesource.com/22600 > > Commit-Queue: Björn Terelius > > Reviewed-by: Elad Alon > > Reviewed-by: Tommi > > Reviewed-by: Erik Språng > > Reviewed-by: Fredrik Solenberg > > Cr-Commit-Position: refs/heads/master@{#20736} > > Change-Id: I2257c46c014adb8c7c4fb28538635cabed1f2229 > Bug: webrtc:8111 > Reviewed-on: https://webrtc-review.googlesource.com/24160 > Reviewed-by: Zhi Huang > Commit-Queue: Zhi Huang > Cr-Commit-Position: refs/heads/master@{#20738} Bug: webrtc:8111 Change-Id: Ie69862cd52d11c1e15adeb6e2caacafe16863c80 Reviewed-on: https://webrtc-review.googlesource.com/24620 Commit-Queue: Björn Terelius Reviewed-by: Elad Alon Reviewed-by: Zhi Huang Reviewed-by: Tommi Reviewed-by: Björn Terelius Cr-Commit-Position: refs/heads/master@{#20811} --- api/peerconnectioninterface.h | 6 +- api/peerconnectionproxy.h | 5 +- .../rtc_event_log/mock/mock_rtc_event_log.h | 7 +- logging/rtc_event_log/rtc_event_log.cc | 98 ++++++++-- logging/rtc_event_log/rtc_event_log.h | 8 +- .../rtc_event_log/rtc_event_log_unittest.cc | 180 ++++++++++++------ pc/peerconnection.cc | 21 +- pc/peerconnection.h | 6 +- pc/peerconnection_integrationtest.cc | 3 +- pc/peerconnectioninterface_unittest.cc | 3 +- video/video_quality_test.cc | 6 +- voice_engine/channel.cc | 3 +- 12 files changed, 245 insertions(+), 101 deletions(-) diff --git a/api/peerconnectioninterface.h b/api/peerconnectioninterface.h index c95cc7d3a2..a682459a13 100644 --- a/api/peerconnectioninterface.h +++ b/api/peerconnectioninterface.h @@ -859,8 +859,10 @@ class PeerConnectionInterface : public rtc::RefCountInterface { // Start RtcEventLog using an existing output-sink. Takes ownership of // |output| and passes it on to Call, which will take the ownership. If the - // operation fails the output will be closed and deallocated. - virtual bool StartRtcEventLog(std::unique_ptr output) { + // operation fails the output will be closed and deallocated. The event log + // will send serialized events to the output object every |output_period_ms|. + virtual bool StartRtcEventLog(std::unique_ptr output, + int64_t output_period_ms) { return false; } diff --git a/api/peerconnectionproxy.h b/api/peerconnectionproxy.h index 78fe4027db..36ee50f9d0 100644 --- a/api/peerconnectionproxy.h +++ b/api/peerconnectionproxy.h @@ -111,7 +111,10 @@ BEGIN_SIGNALING_PROXY_MAP(PeerConnection) PROXY_METHOD0(IceConnectionState, ice_connection_state) PROXY_METHOD0(IceGatheringState, ice_gathering_state) PROXY_METHOD2(bool, StartRtcEventLog, rtc::PlatformFile, int64_t) - PROXY_METHOD1(bool, StartRtcEventLog, std::unique_ptr) + PROXY_METHOD2(bool, + StartRtcEventLog, + std::unique_ptr, + int64_t); PROXY_METHOD0(void, StopRtcEventLog) PROXY_METHOD0(void, Close) END_PROXY_MAP() diff --git a/logging/rtc_event_log/mock/mock_rtc_event_log.h b/logging/rtc_event_log/mock/mock_rtc_event_log.h index 6a4cdbda89..6f69169eff 100644 --- a/logging/rtc_event_log/mock/mock_rtc_event_log.h +++ b/logging/rtc_event_log/mock/mock_rtc_event_log.h @@ -20,10 +20,11 @@ namespace webrtc { class MockRtcEventLog : public RtcEventLog { public: - virtual bool StartLogging(std::unique_ptr output) { - return StartLoggingProxy(output.get()); + virtual bool StartLogging(std::unique_ptr output, + int64_t output_period_ms) { + return StartLoggingProxy(output.get(), output_period_ms); } - MOCK_METHOD1(StartLoggingProxy, bool(RtcEventLogOutput*)); + MOCK_METHOD2(StartLoggingProxy, bool(RtcEventLogOutput*, int64_t)); MOCK_METHOD0(StopLogging, void()); diff --git a/logging/rtc_event_log/rtc_event_log.cc b/logging/rtc_event_log/rtc_event_log.cc index 7e17e6b535..53096de435 100644 --- a/logging/rtc_event_log/rtc_event_log.cc +++ b/logging/rtc_event_log/rtc_event_log.cc @@ -28,6 +28,7 @@ #include "rtc_base/logging.h" #include "rtc_base/ptr_util.h" #include "rtc_base/safe_conversions.h" +#include "rtc_base/safe_minmax.h" #include "rtc_base/sequenced_task_checker.h" #include "rtc_base/task_queue.h" #include "rtc_base/thread_annotations.h" @@ -87,7 +88,8 @@ class RtcEventLogImpl final : public RtcEventLog { // TODO(eladalon): We should change these name to reflect that what we're // actually starting/stopping is the output of the log, not the log itself. - bool StartLogging(std::unique_ptr output) override; + bool StartLogging(std::unique_ptr output, + int64_t output_period_ms) override; void StopLogging() override; void Log(std::unique_ptr event) override; @@ -113,6 +115,8 @@ class RtcEventLogImpl final : public RtcEventLog { void StopLoggingInternal() RTC_RUN_ON(&task_queue_); + void ScheduleOutput() RTC_RUN_ON(&task_queue_); + // Make sure that the event log is "managed" - created/destroyed, as well // as started/stopped - from the same thread/task-queue. rtc::SequencedTaskChecker owner_sequence_checker_; @@ -130,8 +134,15 @@ class RtcEventLogImpl final : public RtcEventLog { std::unique_ptr event_encoder_ RTC_ACCESS_ON(task_queue_); std::unique_ptr event_output_ RTC_ACCESS_ON(task_queue_); - // Keep this last to ensure it destructs first, or else tasks living on the - // queue might access other members after they've been torn down. + size_t num_config_events_written_ RTC_ACCESS_ON(task_queue_); + int64_t output_period_ms_ RTC_ACCESS_ON(task_queue_); + int64_t last_output_ms_ RTC_ACCESS_ON(task_queue_); + bool output_scheduled_ RTC_ACCESS_ON(task_queue_); + + // Since we are posting tasks bound to |this|, it is critical that the event + // log and it's members outlive the |task_queue_|. Keep the "task_queue_| + // last to ensure it destructs first, or else tasks living on the queue might + // access other members after they've been torn down. rtc::TaskQueue task_queue_; RTC_DISALLOW_COPY_AND_ASSIGN(RtcEventLogImpl); @@ -142,6 +153,10 @@ RtcEventLogImpl::RtcEventLogImpl( : max_size_bytes_(std::numeric_limits::max()), written_bytes_(0), event_encoder_(std::move(event_encoder)), + num_config_events_written_(0), + output_period_ms_(kImmediateOutput), + last_output_ms_(rtc::TimeMillis()), + output_scheduled_(false), task_queue_("rtc_event_log") {} RtcEventLogImpl::~RtcEventLogImpl() { @@ -154,10 +169,15 @@ RtcEventLogImpl::~RtcEventLogImpl() { RTC_DCHECK_GE(count, 0); } -bool RtcEventLogImpl::StartLogging(std::unique_ptr output) { +bool RtcEventLogImpl::StartLogging(std::unique_ptr output, + int64_t output_period_ms) { RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); + RTC_DCHECK(output_period_ms == kImmediateOutput || output_period_ms > 0); + if (!output->IsActive()) { + // TODO(eladalon): We may want to remove the IsActive method. Otherwise + // we probably want to be consistent and terminate any existing output. return false; } @@ -170,10 +190,12 @@ bool RtcEventLogImpl::StartLogging(std::unique_ptr output) { // to comply with LogToOutput()'s signature - but it's a small problem. RtcEventLoggingStarted start_event; + // Binding to |this| is safe because |this| outlives the |task_queue_|. auto start = [this, start_event](std::unique_ptr output) { RTC_DCHECK_RUN_ON(&task_queue_); RTC_DCHECK(output->IsActive()); event_output_ = std::move(output); + num_config_events_written_ = 0; LogToOutput(rtc::MakeUnique(start_event)); LogEventsFromMemoryToOutput(); }; @@ -191,8 +213,13 @@ void RtcEventLogImpl::StopLogging() { rtc::Event output_stopped(true, false); + // Binding to |this| is safe because |this| outlives the |task_queue_|. task_queue_.PostTask([this, &output_stopped]() { RTC_DCHECK_RUN_ON(&task_queue_); + if (event_output_) { + RTC_DCHECK(event_output_->IsActive()); + LogEventsFromMemoryToOutput(); + } StopLoggingInternal(); output_stopped.Set(); }); @@ -205,19 +232,53 @@ void RtcEventLogImpl::StopLogging() { void RtcEventLogImpl::Log(std::unique_ptr event) { RTC_DCHECK(event); + // Binding to |this| is safe because |this| outlives the |task_queue_|. auto event_handler = [this](std::unique_ptr unencoded_event) { RTC_DCHECK_RUN_ON(&task_queue_); - if (event_output_) { - LogToOutput(std::move(unencoded_event)); - } else { - LogToMemory(std::move(unencoded_event)); - } + LogToMemory(std::move(unencoded_event)); + if (event_output_) + ScheduleOutput(); }; task_queue_.PostTask(rtc::MakeUnique>( std::move(event), event_handler)); } +void RtcEventLogImpl::ScheduleOutput() { + RTC_DCHECK(event_output_ && event_output_->IsActive()); + if (history_.size() >= kMaxEventsInHistory) { + // We have to emergency drain the buffer. We can't wait for the scheduled + // output task because there might be other event incoming before that. + LogEventsFromMemoryToOutput(); + return; + } + + if (output_period_ms_ == kImmediateOutput) { + // We are already on the |task_queue_| so there is no reason to post a task + // if we want to output immediately. + LogEventsFromMemoryToOutput(); + return; + } + + if (!output_scheduled_) { + output_scheduled_ = true; + // Binding to |this| is safe because |this| outlives the |task_queue_|. + auto output_task = [this]() { + RTC_DCHECK_RUN_ON(&task_queue_); + if (event_output_) { + RTC_DCHECK(event_output_->IsActive()); + LogEventsFromMemoryToOutput(); + } + output_scheduled_ = false; + }; + int64_t now_ms = rtc::TimeMillis(); + int64_t time_since_output_ms = now_ms - last_output_ms_; + uint32_t delay = rtc::SafeClamp(output_period_ms_ - time_since_output_ms, 0, + output_period_ms_); + task_queue_.PostDelayedTask(output_task, delay); + } +} + bool RtcEventLogImpl::AppendEventToString(const RtcEvent& event, std::string* output_string) { RTC_DCHECK_RUN_ON(&task_queue_); @@ -239,14 +300,13 @@ bool RtcEventLogImpl::AppendEventToString(const RtcEvent& event, } void RtcEventLogImpl::LogToMemory(std::unique_ptr event) { - RTC_DCHECK(!event_output_); - std::deque>& container = event->IsConfigEvent() ? config_history_ : history_; const size_t container_max_size = event->IsConfigEvent() ? kMaxEventsInConfigHistory : kMaxEventsInHistory; if (container.size() >= container_max_size) { + RTC_DCHECK(!event_output_); // Shouldn't lose events if we have an output. container.pop_front(); } container.push_back(std::move(event)); @@ -254,17 +314,21 @@ void RtcEventLogImpl::LogToMemory(std::unique_ptr event) { void RtcEventLogImpl::LogEventsFromMemoryToOutput() { RTC_DCHECK(event_output_ && event_output_->IsActive()); + last_output_ms_ = rtc::TimeMillis(); std::string output_string; - // Serialize the config information for all old streams, including streams - // which were already logged to previous outputs. + // Serialize all stream configurations that haven't already been written to + // this output. |num_config_events_written_| is used to track which configs we + // have already written. (Note that the config may have been written to + // previous outputs; configs are not discarded.) bool appended = true; - for (auto& event : config_history_) { - if (!AppendEventToString(*event, &output_string)) { - appended = false; + while (num_config_events_written_ < config_history_.size()) { + appended = AppendEventToString(*config_history_[num_config_events_written_], + &output_string); + if (!appended) break; - } + ++num_config_events_written_; } // Serialize the events in the event queue. diff --git a/logging/rtc_event_log/rtc_event_log.h b/logging/rtc_event_log/rtc_event_log.h index c1c71f07b9..89b4fc1a08 100644 --- a/logging/rtc_event_log/rtc_event_log.h +++ b/logging/rtc_event_log/rtc_event_log.h @@ -13,6 +13,7 @@ #include #include +#include #include "api/rtceventlogoutput.h" #include "logging/rtc_event_log/events/rtc_event.h" @@ -26,6 +27,7 @@ enum PacketDirection { kIncomingPacket = 0, kOutgoingPacket }; class RtcEventLog { public: enum : size_t { kUnlimitedOutput = 0 }; + enum : int64_t { kImmediateOutput = 0 }; // TODO(eladalon): Two stages are upcoming. // 1. Extend this to actually support the new encoding. @@ -49,7 +51,8 @@ class RtcEventLog { // Starts logging to a given output. The output might be limited in size, // and may close itself once it has reached the maximum size. - virtual bool StartLogging(std::unique_ptr output) = 0; + virtual bool StartLogging(std::unique_ptr output, + int64_t output_period_ms) = 0; // Stops logging to file and waits until the file has been closed, after // which it would be permissible to read and/or modify it. @@ -62,7 +65,8 @@ class RtcEventLog { // No-op implementation is used if flag is not set, or in tests. class RtcEventLogNullImpl : public RtcEventLog { public: - bool StartLogging(std::unique_ptr output) override { + bool StartLogging(std::unique_ptr output, + int64_t output_period_ms) override { return false; } void StopLogging() override {} diff --git a/logging/rtc_event_log/rtc_event_log_unittest.cc b/logging/rtc_event_log/rtc_event_log_unittest.cc index 3d4abb3502..fbef901c00 100644 --- a/logging/rtc_event_log/rtc_event_log_unittest.cc +++ b/logging/rtc_event_log/rtc_event_log_unittest.cc @@ -12,6 +12,7 @@ #include #include #include +#include #include #include @@ -299,10 +300,12 @@ void GenerateAudioNetworkAdaptation(const RtpHeaderExtensionMap& extensions, rtc::Optional(prng->Rand()); } -class RtcEventLogSessionDescription { +class RtcEventLogSession + : public ::testing::TestWithParam> { public: - explicit RtcEventLogSessionDescription(unsigned int random_seed) - : prng(random_seed) {} + RtcEventLogSession() + : prng(std::get<0>(GetParam())), + output_period_ms(std::get<1>(GetParam())) {} void GenerateSessionDescription(size_t incoming_rtp_count, size_t outgoing_rtp_count, size_t incoming_rtcp_count, @@ -328,9 +331,10 @@ class RtcEventLogSessionDescription { std::vector sender_configs; std::vector event_types; Random prng; + int64_t output_period_ms; }; -void RtcEventLogSessionDescription::GenerateSessionDescription( +void RtcEventLogSession::GenerateSessionDescription( size_t incoming_rtp_count, size_t outgoing_rtp_count, size_t incoming_rtcp_count, @@ -403,12 +407,14 @@ void RtcEventLogSessionDescription::GenerateSessionDescription( } } -void RtcEventLogSessionDescription::WriteSession() { +void RtcEventLogSession::WriteSession() { // 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(); + std::string test_name = test_info->name(); + std::replace(test_name.begin(), test_name.end(), '/', '_'); const std::string temp_filename = - test::OutputPath() + test_info->test_case_name() + test_info->name(); + test::OutputPath() + "RtcEventLogTest_" + test_name; rtc::ScopedFakeClock fake_clock; fake_clock.SetTimeMicros(prng.Rand()); @@ -432,7 +438,8 @@ void RtcEventLogSessionDescription::WriteSession() { fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); if (i == event_types.size() / 2) log_dumper->StartLogging( - rtc::MakeUnique(temp_filename, 10000000)); + rtc::MakeUnique(temp_filename, 10000000), + output_period_ms); switch (event_types[i]) { case EventType::kIncomingRtp: RTC_CHECK(incoming_rtp_written < incoming_rtp_packets.size()); @@ -516,18 +523,19 @@ void RtcEventLogSessionDescription::WriteSession() { // Read the file and verify that what we read back from the event log is the // same as what we wrote down. -void RtcEventLogSessionDescription::ReadAndVerifySession() { +void RtcEventLogSession::ReadAndVerifySession() { // 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(); + std::string test_name = test_info->name(); + std::replace(test_name.begin(), test_name.end(), '/', '_'); const std::string temp_filename = - test::OutputPath() + test_info->test_case_name() + test_info->name(); + test::OutputPath() + "RtcEventLogTest_" + test_name; // Read the generated file from disk. ParsedRtcEventLog parsed_log; ASSERT_TRUE(parsed_log.ParseFile(temp_filename)); - EXPECT_GE(1000u, event_types.size() + - 2); // The events must fit in the message queue. + EXPECT_GE(5000u, event_types.size() + 2); // The events must fit. EXPECT_EQ(event_types.size() + 2, parsed_log.GetNumberOfEvents()); size_t incoming_rtp_read = 0; @@ -630,7 +638,7 @@ void RtcEventLogSessionDescription::ReadAndVerifySession() { remove(temp_filename.c_str()); } -void RtcEventLogSessionDescription::PrintExpectedEvents(std::ostream& stream) { +void RtcEventLogSession::PrintExpectedEvents(std::ostream& stream) { for (size_t i = 0; i < event_types.size(); i++) { auto it = event_type_to_string.find(event_types[i]); RTC_CHECK(it != event_type_to_string.end()); @@ -649,72 +657,122 @@ void PrintActualEvents(const ParsedRtcEventLog& parsed_log, stream << std::endl; } -TEST(RtcEventLogTest, LogSessionAndReadBack) { +TEST_P(RtcEventLogSession, LogSessionAndReadBack) { RtpHeaderExtensionMap extensions; - RtcEventLogSessionDescription session(321 /*Random seed*/); - session.GenerateSessionDescription(3, // Number of incoming RTP packets. - 2, // Number of outgoing RTP packets. - 1, // Number of incoming RTCP packets. - 1, // Number of outgoing RTCP packets. - 0, // Number of playout events. - 0, // Number of BWE loss events. - 0, // Number of BWE delay events. - extensions, // No extensions. - 0); // Number of contributing sources. - session.WriteSession(); - session.ReadAndVerifySession(); + GenerateSessionDescription(3, // Number of incoming RTP packets. + 2, // Number of outgoing RTP packets. + 1, // Number of incoming RTCP packets. + 1, // Number of outgoing RTCP packets. + 0, // Number of playout events. + 0, // Number of BWE loss events. + 0, // Number of BWE delay events. + extensions, // No extensions. + 0); // Number of contributing sources. + WriteSession(); + ReadAndVerifySession(); } -TEST(RtcEventLogTest, LogSessionAndReadBackWith2Extensions) { +TEST_P(RtcEventLogSession, LogSessionAndReadBackWith2Extensions) { RtpHeaderExtensionMap extensions; extensions.Register(kRtpExtensionAbsoluteSendTime, kAbsoluteSendTimeExtensionId); extensions.Register(kRtpExtensionTransportSequenceNumber, kTransportSequenceNumberExtensionId); - RtcEventLogSessionDescription session(3141592653u /*Random seed*/); - session.GenerateSessionDescription(4, 4, 1, 1, 0, 0, 0, extensions, 0); - session.WriteSession(); - session.ReadAndVerifySession(); + GenerateSessionDescription(4, 4, 1, 1, 0, 0, 0, extensions, 0); + WriteSession(); + ReadAndVerifySession(); } -TEST(RtcEventLogTest, LogSessionAndReadBackWithAllExtensions) { +TEST_P(RtcEventLogSession, LogSessionAndReadBackWithAllExtensions) { RtpHeaderExtensionMap extensions; for (uint32_t i = 0; i < kNumExtensions; i++) { extensions.Register(kExtensionTypes[i], kExtensionIds[i]); } - RtcEventLogSessionDescription session(2718281828u /*Random seed*/); - session.GenerateSessionDescription(5, 4, 1, 1, 3, 2, 2, extensions, 2); - session.WriteSession(); - session.ReadAndVerifySession(); + GenerateSessionDescription(5, 4, 1, 1, 3, 2, 2, extensions, 2); + WriteSession(); + ReadAndVerifySession(); } -TEST(RtcEventLogTest, LogSessionAndReadBackAllCombinations) { - // Try all combinations of header extensions and up to 2 CSRCS. - for (uint32_t extension_selection = 0; - extension_selection < (1u << kNumExtensions); extension_selection++) { - RtpHeaderExtensionMap extensions; - for (uint32_t i = 0; i < kNumExtensions; i++) { - if (extension_selection & (1u << i)) { - extensions.Register(kExtensionTypes[i], kExtensionIds[i]); - } - } - for (uint32_t csrcs_count = 0; csrcs_count < 3; csrcs_count++) { - RtcEventLogSessionDescription session(extension_selection * 3 + - csrcs_count + 1 /*Random seed*/); - session.GenerateSessionDescription( - 2 + extension_selection, // Number of incoming RTP packets. - 2 + extension_selection, // Number of outgoing RTP packets. - 1 + csrcs_count, // Number of incoming RTCP packets. - 1 + csrcs_count, // Number of outgoing RTCP packets. - 3 + csrcs_count, // Number of playout events. - 1 + csrcs_count, // Number of BWE loss events. - 2 + csrcs_count, // Number of BWE delay events. - extensions, // Bit vector choosing extensions. - csrcs_count); // Number of contributing sources. - session.WriteSession(); - session.ReadAndVerifySession(); - } +TEST_P(RtcEventLogSession, LogLongSessionAndReadBack) { + RtpHeaderExtensionMap extensions; + for (uint32_t i = 0; i < kNumExtensions; i++) { + extensions.Register(kExtensionTypes[i], kExtensionIds[i]); } + GenerateSessionDescription(1000, 1000, 250, 250, 200, 100, 100, extensions, + 1); + WriteSession(); + ReadAndVerifySession(); } +TEST(RtcEventLogTest, CircularBufferKeepsMostRecentEvents) { + constexpr size_t kNumEvents = 20000; + constexpr int64_t kStartTime = 1000000; + + auto test_info = ::testing::UnitTest::GetInstance()->current_test_info(); + std::string test_name = test_info->name(); + std::replace(test_name.begin(), test_name.end(), '/', '_'); + const std::string temp_filename = + test::OutputPath() + "RtcEventLogTest_" + test_name; + + rtc::ScopedFakeClock fake_clock; + fake_clock.SetTimeMicros(kStartTime); + + // When log_dumper goes out of scope, it causes the log file to be flushed + // to disk. + std::unique_ptr log_dumper( + RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); + + for (size_t i = 0; i < kNumEvents; i++) { + // The purpose of the test is to verify that the log can handle + // more events than what fits in the internal circular buffer. The exact + // type of events does not matter so we chose AudioPlayouts for simplicity. + // We use the index as an ssrc to get a strict relationship between the ssrc + // and the timestamp. We use this for some basic consistency checks when we + // read back. + log_dumper->Log(rtc::MakeUnique(i)); + fake_clock.AdvanceTimeMicros(10000); + } + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000), + RtcEventLog::kImmediateOutput); + log_dumper->StopLogging(); + + // Read the generated file from disk. + ParsedRtcEventLog parsed_log; + ASSERT_TRUE(parsed_log.ParseFile(temp_filename)); + // If the following fails, it probably means that kNumEvents isn't larger + // than the size of the cyclic buffer in the event log. Try increasing + // kNumEvents. + EXPECT_LT(parsed_log.GetNumberOfEvents(), kNumEvents); + // We expect a start event, some number of playouts events and a stop event. + EXPECT_GT(parsed_log.GetNumberOfEvents(), 2u); + + RtcEventLogTestHelper::VerifyLogStartEvent(parsed_log, 0); + rtc::Optional last_timestamp; + rtc::Optional last_ssrc; + for (size_t i = 1; i < parsed_log.GetNumberOfEvents() - 1; i++) { + EXPECT_EQ(parsed_log.GetEventType(i), + ParsedRtcEventLog::EventType::AUDIO_PLAYOUT_EVENT); + uint32_t ssrc; + parsed_log.GetAudioPlayout(i, &ssrc); + int64_t timestamp = parsed_log.GetTimestamp(i); + EXPECT_LT(ssrc, kNumEvents); + EXPECT_EQ(static_cast(kStartTime + 10000 * ssrc), timestamp); + if (last_ssrc) + EXPECT_EQ(ssrc, *last_ssrc + 1); + if (last_timestamp) + EXPECT_EQ(timestamp, *last_timestamp + 10000); + last_ssrc = ssrc; + last_timestamp = timestamp; + } + RtcEventLogTestHelper::VerifyLogEndEvent(parsed_log, + parsed_log.GetNumberOfEvents() - 1); +} + +INSTANTIATE_TEST_CASE_P( + RtcEventLogTest, + RtcEventLogSession, + ::testing::Combine(::testing::Values(1234567, 7654321), + ::testing::Values(RtcEventLog::kImmediateOutput, 1, 5))); + } // namespace webrtc diff --git a/pc/peerconnection.cc b/pc/peerconnection.cc index 53c891ef04..e4864c9795 100644 --- a/pc/peerconnection.cc +++ b/pc/peerconnection.cc @@ -1956,19 +1956,23 @@ bool PeerConnection::StartRtcEventLog(rtc::PlatformFile file, ? RtcEventLog::kUnlimitedOutput : rtc::saturated_cast(max_size_bytes); return StartRtcEventLog( - rtc::MakeUnique(file, max_size)); + rtc::MakeUnique(file, max_size), + webrtc::RtcEventLog::kImmediateOutput); } -bool PeerConnection::StartRtcEventLog( - std::unique_ptr output) { +bool PeerConnection::StartRtcEventLog(std::unique_ptr output, + int64_t output_period_ms) { // TODO(eladalon): In C++14, this can be done with a lambda. struct Functor { - bool operator()() { return pc->StartRtcEventLog_w(std::move(output)); } + bool operator()() { + return pc->StartRtcEventLog_w(std::move(output), output_period_ms); + } PeerConnection* const pc; std::unique_ptr output; + const int64_t output_period_ms; }; - return worker_thread()->Invoke(RTC_FROM_HERE, - Functor{this, std::move(output)}); + return worker_thread()->Invoke( + RTC_FROM_HERE, Functor{this, std::move(output), output_period_ms}); } void PeerConnection::StopRtcEventLog() { @@ -3203,11 +3207,12 @@ MetricsObserverInterface* PeerConnection::metrics_observer() const { } bool PeerConnection::StartRtcEventLog_w( - std::unique_ptr output) { + std::unique_ptr output, + int64_t output_period_ms) { if (!event_log_) { return false; } - return event_log_->StartLogging(std::move(output)); + return event_log_->StartLogging(std::move(output), output_period_ms); } void PeerConnection::StopRtcEventLog_w() { diff --git a/pc/peerconnection.h b/pc/peerconnection.h index 0b00588ee1..2b36a86e49 100644 --- a/pc/peerconnection.h +++ b/pc/peerconnection.h @@ -177,7 +177,8 @@ class PeerConnection : public PeerConnectionInterface, RTC_DEPRECATED bool StartRtcEventLog(rtc::PlatformFile file, int64_t max_size_bytes) override; - bool StartRtcEventLog(std::unique_ptr output) override; + bool StartRtcEventLog(std::unique_ptr output, + int64_t output_period_ms) override; void StopRtcEventLog() override; void Close() override; @@ -505,7 +506,8 @@ class PeerConnection : public PeerConnectionInterface, // Starts output of an RTC event log to the given output object. // This function should only be called from the worker thread. - bool StartRtcEventLog_w(std::unique_ptr output); + bool StartRtcEventLog_w(std::unique_ptr output, + int64_t output_period_ms); // Stops recording an RTC event log. // This function should only be called from the worker thread. diff --git a/pc/peerconnection_integrationtest.cc b/pc/peerconnection_integrationtest.cc index 2fc471cd01..90aad09078 100644 --- a/pc/peerconnection_integrationtest.cc +++ b/pc/peerconnection_integrationtest.cc @@ -3521,7 +3521,8 @@ TEST_F(PeerConnectionIntegrationTest, RtcEventLogOutputWriteCalled) { ON_CALL(*output, IsActive()).WillByDefault(testing::Return(true)); ON_CALL(*output, Write(::testing::_)).WillByDefault(testing::Return(true)); EXPECT_CALL(*output, Write(::testing::_)).Times(::testing::AtLeast(1)); - EXPECT_TRUE(caller()->pc()->StartRtcEventLog(std::move(output))); + EXPECT_TRUE(caller()->pc()->StartRtcEventLog( + std::move(output), webrtc::RtcEventLog::kImmediateOutput)); caller()->AddAudioVideoMediaStream(); caller()->CreateAndSetAndSignalOffer(); diff --git a/pc/peerconnectioninterface_unittest.cc b/pc/peerconnectioninterface_unittest.cc index b0423a365e..409fa91f62 100644 --- a/pc/peerconnectioninterface_unittest.cc +++ b/pc/peerconnectioninterface_unittest.cc @@ -3246,7 +3246,8 @@ TEST_F(PeerConnectionInterfaceTest, rtc::PlatformFile file = 0; int64_t max_size_bytes = 1024; EXPECT_FALSE(pc_->StartRtcEventLog( - rtc::MakeUnique(file, max_size_bytes))); + rtc::MakeUnique(file, max_size_bytes), + webrtc::RtcEventLog::kImmediateOutput)); pc_->StopRtcEventLog(); } diff --git a/video/video_quality_test.cc b/video/video_quality_test.cc index 198b73ced7..512a9bbfe3 100644 --- a/video/video_quality_test.cc +++ b/video/video_quality_test.cc @@ -1800,9 +1800,11 @@ void VideoQualityTest::RunWithAnalyzer(const Params& params) { if (!params.logging.rtc_event_log_name.empty()) { event_log_ = RtcEventLog::Create(clock_, RtcEventLog::EncodingType::Legacy); - bool event_log_started = - event_log_->StartLogging(rtc::MakeUnique( + std::unique_ptr output( + rtc::MakeUnique( params.logging.rtc_event_log_name, RtcEventLog::kUnlimitedOutput)); + bool event_log_started = event_log_->StartLogging( + std::move(output), RtcEventLog::kImmediateOutput); RTC_DCHECK(event_log_started); } diff --git a/voice_engine/channel.cc b/voice_engine/channel.cc index c870ece7fe..20dc87f6c4 100644 --- a/voice_engine/channel.cc +++ b/voice_engine/channel.cc @@ -65,7 +65,8 @@ class RtcEventLogProxy final : public webrtc::RtcEventLog { public: RtcEventLogProxy() : event_log_(nullptr) {} - bool StartLogging(std::unique_ptr output) override { + bool StartLogging(std::unique_ptr output, + int64_t output_period_ms) override { RTC_NOTREACHED(); return false; }