Chromium Code Reviews| 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 |