Index: webrtc/call/rtc_event_log.cc |
diff --git a/webrtc/call/rtc_event_log.cc b/webrtc/call/rtc_event_log.cc |
index 361db81c068ccc99b480918ad55c05cbd1be1656..a7f1245e87bd0c9804a69d7a2ea515b21ba0bf96 100644 |
--- a/webrtc/call/rtc_event_log.cc |
+++ b/webrtc/call/rtc_event_log.cc |
@@ -10,18 +10,22 @@ |
#include "webrtc/call/rtc_event_log.h" |
-#include <deque> |
+#include <limits> |
#include <vector> |
#include "webrtc/base/checks.h" |
-#include "webrtc/base/criticalsection.h" |
-#include "webrtc/base/thread_annotations.h" |
+#include "webrtc/base/constructormagic.h" |
+#include "webrtc/base/event.h" |
+#include "webrtc/base/thread_checker.h" |
#include "webrtc/call.h" |
+#include "webrtc/call/rtc_event_log_helper_thread.h" |
+#include "webrtc/common_audio/swap_queue.h" |
#include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h" |
#include "webrtc/modules/rtp_rtcp/source/byte_io.h" |
#include "webrtc/modules/rtp_rtcp/source/rtcp_utility.h" |
#include "webrtc/system_wrappers/include/clock.h" |
#include "webrtc/system_wrappers/include/file_wrapper.h" |
+#include "webrtc/system_wrappers/include/logging.h" |
#ifdef ENABLE_RTC_EVENT_LOG |
// Files generated at build-time by the protobuf compiler. |
@@ -37,12 +41,20 @@ namespace webrtc { |
#ifndef ENABLE_RTC_EVENT_LOG |
// No-op implementation if flag is not set. |
-class RtcEventLogImpl final : public RtcEventLog { |
+class RtcEventLogNullImpl 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 {} |
+ bool StartLogging(const std::string& file_name, |
+ int64_t max_size_bytes) override { |
+ return false; |
+ } |
+ bool StartLogging(rtc::PlatformFile platform_file, |
+ int64_t max_size_bytes) override { |
+ return false; |
+ } |
+ void StopLogging() override {} |
+ // We don't want to hide the deprecated versions coming from the base class. |
+ using RtcEventLog::StartLogging; |
the sun
2016/02/25 15:23:19
Not necessary.
terelius
2016/03/09 19:49:39
Fixed.
|
+ |
void LogVideoReceiveStreamConfig( |
const VideoReceiveStream::Config& config) override {} |
void LogVideoSendStreamConfig( |
@@ -65,11 +77,15 @@ 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; |
+ explicit RtcEventLogImpl(const Clock* clock); |
+ ~RtcEventLogImpl() override; |
+ |
+ bool StartLogging(const std::string& file_name, |
+ int64_t max_size_bytes) override; |
+ bool StartLogging(rtc::PlatformFile platform_file, |
+ int64_t max_size_bytes) override; |
+ // We don't want to hide the deprecated versions coming from the base class. |
+ using RtcEventLog::StartLogging; |
the sun
2016/02/25 15:23:19
Not necessary.
terelius
2016/03/09 19:49:39
Fixed.
|
void StopLogging() override; |
void LogVideoReceiveStreamConfig( |
const VideoReceiveStream::Config& config) override; |
@@ -88,37 +104,25 @@ class RtcEventLogImpl final : public RtcEventLog { |
int32_t total_packets) override; |
private: |
- // Starts logging. This function assumes the file_ has been opened succesfully |
- // and that the start_time_us_ and _duration_us_ have been set. |
- void StartLoggingLocked() EXCLUSIVE_LOCKS_REQUIRED(crit_); |
- // Stops logging and clears the stored data and buffers. |
- void StopLoggingLocked() EXCLUSIVE_LOCKS_REQUIRED(crit_); |
- // Adds a new event to the logfile if logging is active, or adds it to the |
- // list of recent log events otherwise. |
- void HandleEvent(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_); |
- // Writes the event to the file. Note that this will destroy the state of the |
- // input argument. |
- void StoreToFile(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_); |
- // Adds the event to the list of recent events, and removes any events that |
- // are too old and no longer fall in the time window. |
- void AddRecentEvent(const rtclog::Event& event) |
- EXCLUSIVE_LOCKS_REQUIRED(crit_); |
- |
- rtc::CriticalSection crit_; |
- rtc::scoped_ptr<FileWrapper> file_ GUARDED_BY(crit_) = |
- rtc::scoped_ptr<FileWrapper>(FileWrapper::Create()); |
- rtc::PlatformFile platform_file_ GUARDED_BY(crit_) = |
- rtc::kInvalidPlatformFileValue; |
- rtclog::EventStream stream_ GUARDED_BY(crit_); |
- std::deque<rtclog::Event> recent_log_events_ GUARDED_BY(crit_); |
- 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_); |
+ // Message queue for passing control messages to the logging thread. |
+ SwapQueue<EventLogMessage> message_queue_; |
the sun
2016/02/25 15:23:19
Note, you don't really need one queue per event ty
stefan-webrtc
2016/03/01 09:44:16
We plan on using the event log in other places too
ivoc
2016/03/01 10:04:57
I'm still not convinced that a single queue is a b
terelius
2016/03/01 11:24:04
We *are* logging from a single point in time.
Hav
the sun
2016/03/02 10:09:16
But since we're not using any of those optimizatio
|
+ |
+ // Message queues for passing events to the logging thread. |
+ SwapQueue<rtclog::Event> config_queue_; |
+ SwapQueue<rtclog::Event> rtp_queue_; |
+ SwapQueue<rtclog::Event> rtcp_queue_; |
+ SwapQueue<rtclog::Event> acm_playout_queue_; |
+ SwapQueue<rtclog::Event> bwe_loss_queue_; |
+ |
+ rtc::Event wake_up_; |
+ rtc::Event stopped_; |
+ |
const Clock* const clock_; |
+ |
+ RtcEventLogHelperThread helper_thread_; |
+ rtc::ThreadChecker thread_checker_; |
+ |
+ RTC_DISALLOW_IMPLICIT_CONSTRUCTORS(RtcEventLogImpl); |
}; |
namespace { |
@@ -126,10 +130,6 @@ namespace { |
// that the rest of the WebRtc project can use, to the corresponding |
// serialized enum which is defined by the protobuf. |
-// Do not add default return values to the conversion functions in this |
-// unnamed namespace. The intention is to make the compiler warn if anyone |
-// adds unhandled new events/modes/etc. |
- |
rtclog::VideoReceiveConfig_RtcpMode ConvertRtcpMode(RtcpMode rtcp_mode) { |
switch (rtcp_mode) { |
case RtcpMode::kCompound: |
@@ -159,108 +159,105 @@ rtclog::MediaType ConvertMediaType(MediaType media_type) { |
return rtclog::ANY; |
} |
-} // namespace |
+// The RTP and RTCP buffers reserve space for twice the expected number of |
+// sent packets because they also contain received packets. |
+const int kStreamConfigsPerSecond = 64; // 16 clients w. 4 streams each. |
+const int kRtpPacketsPerSecond = 500; // 125 sent video packets/s @ 1 Mbps. |
+const int kRtcpPacketsPerSecond = 40; // Assume RTCP sent 20 times/s. |
+const int kPlayoutsPerSecond = 100; // Playout called every 10 ms. |
+const int kBweUpdatesPerSecond = 20; // One BWE update per RTCP packet. |
-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; |
-} |
+const int kControlMessagesPerSecond = 5; |
} // 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()) { |
+RtcEventLogImpl::RtcEventLogImpl(const Clock* clock) |
+ // Allocate buffers for roughly one second of history. |
+ : message_queue_(kControlMessagesPerSecond), |
+ config_queue_(kStreamConfigsPerSecond), |
+ rtp_queue_(kRtpPacketsPerSecond), |
+ rtcp_queue_(kRtcpPacketsPerSecond), |
+ acm_playout_queue_(kPlayoutsPerSecond), |
+ bwe_loss_queue_(kBweUpdatesPerSecond), |
+ wake_up_(false, false), |
+ stopped_(false, false), |
+ clock_(clock), |
+ helper_thread_(&message_queue_, |
+ &config_queue_, |
+ &rtp_queue_, |
+ &rtcp_queue_, |
+ &acm_playout_queue_, |
+ &bwe_loss_queue_, |
+ &wake_up_, |
+ &stopped_, |
+ clock), |
+ thread_checker_() { |
+ thread_checker_.DetachFromThread(); |
} |
-void RtcEventLogImpl::SetBufferDuration(int64_t buffer_duration_us) { |
- rtc::CritScope lock(&crit_); |
- buffer_duration_us_ = buffer_duration_us; |
+RtcEventLogImpl::~RtcEventLogImpl() { |
+ // The RtcEventLogHelperThread destructor closes the file |
+ // and waits for the thread to terminate. |
} |
-void RtcEventLogImpl::StartLogging(const std::string& file_name, |
- int duration_ms) { |
- rtc::CritScope lock(&crit_); |
- if (currently_logging_) { |
- StopLoggingLocked(); |
+bool RtcEventLogImpl::StartLogging(const std::string& file_name, |
+ int64_t max_size_bytes) { |
+ EventLogMessage message; |
+ message.message_type = EventLogMessage::START_FILE; |
+ message.max_size_bytes = max_size_bytes; |
+ message.start_time = clock_->TimeInMicroseconds(); |
+ message.stop_time = std::numeric_limits<int64_t>::max(); |
+ message.file.reset(FileWrapper::Create()); |
+ if (message.file->OpenFile(file_name.c_str(), false) != 0) { |
+ return false; |
} |
- if (file_->OpenFile(file_name.c_str(), false) != 0) { |
- return; |
+ if (!message_queue_.Insert(&message)) { |
+ LOG(LS_WARNING) << "Message queue full. Can't start logging."; |
+ return false; |
} |
- start_time_us_ = clock_->TimeInMicroseconds(); |
- duration_us_ = static_cast<int64_t>(duration_ms) * 1000; |
- StartLoggingLocked(); |
+ return true; |
} |
-bool RtcEventLogImpl::StartLogging(rtc::PlatformFile log_file) { |
- rtc::CritScope lock(&crit_); |
- |
- if (currently_logging_) { |
- StopLoggingLocked(); |
+bool RtcEventLogImpl::StartLogging(rtc::PlatformFile platform_file, |
+ int64_t max_size_bytes) { |
+ EventLogMessage message; |
+ message.message_type = EventLogMessage::START_FILE; |
+ message.max_size_bytes = max_size_bytes; |
+ message.start_time = clock_->TimeInMicroseconds(); |
+ message.stop_time = std::numeric_limits<int64_t>::max(); |
+ message.file.reset(FileWrapper::Create()); |
+ FILE* file_handle = rtc::FdopenPlatformFileForWriting(platform_file); |
+ if (!file_handle) { |
+ return false; |
} |
- RTC_DCHECK(platform_file_ == rtc::kInvalidPlatformFileValue); |
- |
- FILE* file_stream = rtc::FdopenPlatformFileForWriting(log_file); |
- if (!file_stream) { |
- rtc::ClosePlatformFile(log_file); |
+ if (message.file->OpenFromFileHandle(file_handle, true, false) != 0) { |
return false; |
} |
- |
- if (file_->OpenFromFileHandle(file_stream, true, false) != 0) { |
- rtc::ClosePlatformFile(log_file); |
+ if (!message_queue_.Insert(&message)) { |
+ LOG(LS_WARNING) << "Message queue full. Can't start logging."; |
return false; |
} |
- platform_file_ = log_file; |
- // Set the start time and duration to keep logging for 10 minutes. |
- start_time_us_ = clock_->TimeInMicroseconds(); |
- duration_us_ = 10 * 60 * 1000000; |
- StartLoggingLocked(); |
return true; |
} |
-void RtcEventLogImpl::StartLoggingLocked() { |
- currently_logging_ = true; |
- |
- // 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 (IsConfigEvent(event)) { |
- StoreToFile(&event); |
- config_events_.push_back(event); |
- } else if (event.timestamp_us() >= start_time_us_ - buffer_duration_us_) { |
- StoreToFile(&event); |
- } |
- } |
- recent_log_events_.clear(); |
- // Write a LOG_START event to the file. |
- rtclog::Event start_event; |
- start_event.set_timestamp_us(start_time_us_); |
- start_event.set_type(rtclog::Event::LOG_START); |
- StoreToFile(&start_event); |
-} |
- |
void RtcEventLogImpl::StopLogging() { |
- rtc::CritScope lock(&crit_); |
- StopLoggingLocked(); |
+ RTC_DCHECK(thread_checker_.CalledOnValidThread()); |
the sun
2016/02/25 15:23:19
Why just here? Add to StartLogging() too?
terelius
2016/03/09 19:49:39
Done.
|
+ EventLogMessage message; |
+ message.message_type = EventLogMessage::STOP_FILE; |
+ message.stop_time = clock_->TimeInMicroseconds(); |
+ if (!message_queue_.Insert(&message)) { |
+ // TODO(terelius): We would like to have a blocking Insert function in the |
+ // SwapQueue, but for the time being we will just assume that the message |
+ // queue never gets full. |
+ LOG(LS_WARNING) << "Message queue full. Can't stop logging."; |
+ return; |
stefan-webrtc
2016/03/01 09:44:16
Will we be able to make sure the caller tries to s
terelius
2016/03/09 19:49:39
This would happen if the user tries to start loggi
|
+ } |
+ wake_up_.Set(); // Request the output thread to wake up. |
+ stopped_.Wait(rtc::Event::kForever); // Wait for the log to stop. |
} |
void RtcEventLogImpl::LogVideoReceiveStreamConfig( |
const VideoReceiveStream::Config& config) { |
- rtc::CritScope lock(&crit_); |
- |
rtclog::Event event; |
event.set_timestamp_us(clock_->TimeInMicroseconds()); |
event.set_type(rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT); |
@@ -292,13 +289,13 @@ void RtcEventLogImpl::LogVideoReceiveStreamConfig( |
decoder->set_name(d.payload_name); |
decoder->set_payload_type(d.payload_type); |
} |
- HandleEvent(&event); |
+ if (!config_queue_.Insert(&event)) { |
+ LOG(LS_WARNING) << "Config queue full. Not logging config event."; |
+ } |
} |
void RtcEventLogImpl::LogVideoSendStreamConfig( |
const VideoSendStream::Config& config) { |
- rtc::CritScope lock(&crit_); |
- |
rtclog::Event event; |
event.set_timestamp_us(clock_->TimeInMicroseconds()); |
event.set_type(rtclog::Event::VIDEO_SENDER_CONFIG_EVENT); |
@@ -324,7 +321,9 @@ 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); |
- HandleEvent(&event); |
+ if (!config_queue_.Insert(&event)) { |
+ LOG(LS_WARNING) << "Config queue full. Not logging config event."; |
+ } |
} |
void RtcEventLogImpl::LogRtpHeader(PacketDirection direction, |
@@ -347,7 +346,6 @@ void RtcEventLogImpl::LogRtpHeader(PacketDirection direction, |
header_length += (x_len + 1) * 4; |
} |
- rtc::CritScope lock(&crit_); |
rtclog::Event rtp_event; |
rtp_event.set_timestamp_us(clock_->TimeInMicroseconds()); |
rtp_event.set_type(rtclog::Event::RTP_EVENT); |
@@ -355,14 +353,15 @@ void RtcEventLogImpl::LogRtpHeader(PacketDirection direction, |
rtp_event.mutable_rtp_packet()->set_type(ConvertMediaType(media_type)); |
rtp_event.mutable_rtp_packet()->set_packet_length(packet_length); |
rtp_event.mutable_rtp_packet()->set_header(header, header_length); |
- HandleEvent(&rtp_event); |
+ if (!rtp_queue_.Insert(&rtp_event)) { |
+ LOG(LS_WARNING) << "RTP queue full. Not logging RTP packet."; |
+ } |
} |
void RtcEventLogImpl::LogRtcpPacket(PacketDirection direction, |
MediaType media_type, |
const uint8_t* packet, |
size_t length) { |
- rtc::CritScope lock(&crit_); |
rtclog::Event rtcp_event; |
rtcp_event.set_timestamp_us(clock_->TimeInMicroseconds()); |
rtcp_event.set_type(rtclog::Event::RTCP_EVENT); |
@@ -414,23 +413,25 @@ void RtcEventLogImpl::LogRtcpPacket(PacketDirection direction, |
block_begin += block_size; |
} |
rtcp_event.mutable_rtcp_packet()->set_packet_data(buffer, buffer_length); |
- HandleEvent(&rtcp_event); |
+ if (!rtcp_queue_.Insert(&rtcp_event)) { |
+ LOG(LS_WARNING) << "RTCP queue full. Not logging RTCP packet."; |
+ } |
} |
void RtcEventLogImpl::LogAudioPlayout(uint32_t ssrc) { |
- rtc::CritScope lock(&crit_); |
rtclog::Event event; |
event.set_timestamp_us(clock_->TimeInMicroseconds()); |
event.set_type(rtclog::Event::AUDIO_PLAYOUT_EVENT); |
auto playout_event = event.mutable_audio_playout_event(); |
playout_event->set_local_ssrc(ssrc); |
- HandleEvent(&event); |
+ if (!acm_playout_queue_.Insert(&event)) { |
+ LOG(LS_WARNING) << "Playout queue full. Not logging ACM playout."; |
+ } |
} |
void RtcEventLogImpl::LogBwePacketLossEvent(int32_t bitrate, |
uint8_t fraction_loss, |
int32_t total_packets) { |
- rtc::CritScope lock(&crit_); |
rtclog::Event event; |
event.set_timestamp_us(clock_->TimeInMicroseconds()); |
event.set_type(rtclog::Event::BWE_PACKET_LOSS_EVENT); |
@@ -438,62 +439,8 @@ void RtcEventLogImpl::LogBwePacketLossEvent(int32_t bitrate, |
bwe_event->set_bitrate(bitrate); |
bwe_event->set_fraction_loss(fraction_loss); |
bwe_event->set_total_packets(total_packets); |
- HandleEvent(&event); |
-} |
- |
-void RtcEventLogImpl::StopLoggingLocked() { |
- if (currently_logging_) { |
- currently_logging_ = false; |
- // Create a LogEnd event |
- rtclog::Event event; |
- event.set_timestamp_us(clock_->TimeInMicroseconds()); |
- event.set_type(rtclog::Event::LOG_END); |
- // Store the event and close the file |
- RTC_DCHECK(file_->Open()); |
- StoreToFile(&event); |
- file_->CloseFile(); |
- if (platform_file_ != rtc::kInvalidPlatformFileValue) { |
- rtc::ClosePlatformFile(platform_file_); |
- platform_file_ = rtc::kInvalidPlatformFileValue; |
- } |
- } |
- RTC_DCHECK(!file_->Open()); |
- stream_.Clear(); |
-} |
- |
-void RtcEventLogImpl::HandleEvent(rtclog::Event* event) { |
- if (currently_logging_) { |
- if (clock_->TimeInMicroseconds() < start_time_us_ + duration_us_) { |
- StoreToFile(event); |
- return; |
- } |
- StopLoggingLocked(); |
- } |
- AddRecentEvent(*event); |
-} |
- |
-void RtcEventLogImpl::StoreToFile(rtclog::Event* event) { |
- // Reuse the same object at every log event. |
- if (stream_.stream_size() < 1) { |
- stream_.add_stream(); |
- } |
- RTC_DCHECK_EQ(stream_.stream_size(), 1); |
- stream_.mutable_stream(0)->Swap(event); |
- // TODO(terelius): Doesn't this create a new EventStream per event? |
- // Is this guaranteed to work e.g. in future versions of protobuf? |
- std::string dump_buffer; |
- stream_.SerializeToString(&dump_buffer); |
- file_->Write(dump_buffer.data(), dump_buffer.size()); |
-} |
- |
-void RtcEventLogImpl::AddRecentEvent(const rtclog::Event& event) { |
- recent_log_events_.push_back(event); |
- while (recent_log_events_.front().timestamp_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(); |
+ if (!bwe_loss_queue_.Insert(&event)) { |
+ LOG(LS_WARNING) << "BWE loss queue full. Not logging BWE update."; |
} |
} |
@@ -516,8 +463,12 @@ bool RtcEventLog::ParseRtcEventLog(const std::string& file_name, |
#endif // ENABLE_RTC_EVENT_LOG |
// RtcEventLog member functions. |
-rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() { |
- return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl()); |
+rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create(const Clock* clock) { |
+#ifdef ENABLE_RTC_EVENT_LOG |
+ return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl(clock)); |
+#else |
+ return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogNullImpl()); |
+#endif // ENABLE_RTC_EVENT_LOG |
} |
} // namespace webrtc |