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}
diff --git a/webrtc/call/rtc_event_log.cc b/webrtc/call/rtc_event_log.cc
index 6a15912..dd7a3b6 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 <deque>
+#include <vector>
#include "webrtc/base/checks.h"
#include "webrtc/base/criticalsection.h"
@@ -36,6 +37,7 @@
// 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 {
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 @@
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<FileWrapper> file_ GUARDED_BY(crit_) =
rtc::scoped_ptr<FileWrapper>(FileWrapper::Create());
@@ -102,10 +103,14 @@
rtc::kInvalidPlatformFileValue;
rtclog::EventStream stream_ GUARDED_BY(crit_);
std::deque<rtclog::Event> 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<rtclog::Event> 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 @@
} // 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 @@
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 @@
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 @@
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::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 @@
rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
}
+
} // namespace webrtc
diff --git a/webrtc/call/rtc_event_log.h b/webrtc/call/rtc_event_log.h
index 02bbdc6..85d7525 100644
--- a/webrtc/call/rtc_event_log.h
+++ b/webrtc/call/rtc_event_log.h
@@ -36,6 +36,10 @@
static rtc::scoped_ptr<RtcEventLog> 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 536b997..cae2a20 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 @@
}
}
-// 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<rtc::Buffer> rtp_packets;
@@ -476,7 +477,9 @@
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 @@
}
}
+// 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<RtcEventLog> 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
