Chromium Code Reviews| OLD | NEW | 
|---|---|
| 1 /* | 1 /* | 
| 2 * Copyright (c) 2015 The WebRTC project authors. All Rights Reserved. | 2 * Copyright (c) 2015 The WebRTC project authors. All Rights Reserved. | 
| 3 * | 3 * | 
| 4 * Use of this source code is governed by a BSD-style license | 4 * Use of this source code is governed by a BSD-style license | 
| 5 * that can be found in the LICENSE file in the root of the source | 5 * that can be found in the LICENSE file in the root of the source | 
| 6 * tree. An additional intellectual property rights grant can be found | 6 * tree. An additional intellectual property rights grant can be found | 
| 7 * in the file PATENTS. All contributing project authors may | 7 * in the file PATENTS. All contributing project authors may | 
| 8 * be found in the AUTHORS file in the root of the source tree. | 8 * be found in the AUTHORS file in the root of the source tree. | 
| 9 */ | 9 */ | 
| 10 | 10 | 
| 11 #include "webrtc/logging/rtc_event_log/rtc_event_log.h" | 11 #include "webrtc/logging/rtc_event_log/rtc_event_log.h" | 
| 12 | 12 | 
| 13 #include <atomic> | |
| 14 #include <deque> | |
| 15 #include <functional> | |
| 13 #include <limits> | 16 #include <limits> | 
| 17 #include <memory> | |
| 14 #include <utility> | 18 #include <utility> | 
| 15 #include <vector> | 19 #include <vector> | 
| 16 | 20 | 
| 17 #include "webrtc/logging/rtc_event_log/rtc_event_log_helper_thread.h" | |
| 18 #include "webrtc/modules/audio_coding/audio_network_adaptor/include/audio_networ k_adaptor.h" | 21 #include "webrtc/modules/audio_coding/audio_network_adaptor/include/audio_networ k_adaptor.h" | 
| 19 #include "webrtc/modules/remote_bitrate_estimator/include/bwe_defines.h" | 22 #include "webrtc/modules/remote_bitrate_estimator/include/bwe_defines.h" | 
| 20 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h" | 23 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h" | 
| 21 #include "webrtc/modules/rtp_rtcp/source/byte_io.h" | 24 #include "webrtc/modules/rtp_rtcp/source/byte_io.h" | 
| 22 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/app.h" | 25 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/app.h" | 
| 23 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/bye.h" | 26 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/bye.h" | 
| 24 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/common_header.h" | 27 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/common_header.h" | 
| 25 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/extended_jitter_report.h" | 28 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/extended_jitter_report.h" | 
| 26 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/extended_reports.h" | 29 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/extended_reports.h" | 
| 27 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/psfb.h" | 30 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/psfb.h" | 
| 28 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/receiver_report.h" | 31 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/receiver_report.h" | 
| 29 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/rtpfb.h" | 32 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/rtpfb.h" | 
| 30 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/sdes.h" | 33 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/sdes.h" | 
| 31 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/sender_report.h" | 34 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/sender_report.h" | 
| 32 #include "webrtc/rtc_base/atomicops.h" | |
| 33 #include "webrtc/rtc_base/checks.h" | 35 #include "webrtc/rtc_base/checks.h" | 
| 34 #include "webrtc/rtc_base/constructormagic.h" | 36 #include "webrtc/rtc_base/constructormagic.h" | 
| 35 #include "webrtc/rtc_base/event.h" | 37 #include "webrtc/rtc_base/event.h" | 
| 38 #include "webrtc/rtc_base/ignore_wundef.h" | |
| 36 #include "webrtc/rtc_base/logging.h" | 39 #include "webrtc/rtc_base/logging.h" | 
| 37 #include "webrtc/rtc_base/protobuf_utils.h" | 40 #include "webrtc/rtc_base/protobuf_utils.h" | 
| 38 #include "webrtc/rtc_base/swap_queue.h" | 41 #include "webrtc/rtc_base/ptr_util.h" | 
| 39 #include "webrtc/rtc_base/thread_checker.h" | 42 #include "webrtc/rtc_base/sequenced_task_checker.h" | 
| 43 #include "webrtc/rtc_base/task_queue.h" | |
| 44 #include "webrtc/rtc_base/thread_annotations.h" | |
| 40 #include "webrtc/rtc_base/timeutils.h" | 45 #include "webrtc/rtc_base/timeutils.h" | 
| 41 #include "webrtc/system_wrappers/include/file_wrapper.h" | 46 #include "webrtc/system_wrappers/include/file_wrapper.h" | 
| 47 #include "webrtc/typedefs.h" | |
| 42 | 48 | 
| 43 #ifdef ENABLE_RTC_EVENT_LOG | 49 #ifdef ENABLE_RTC_EVENT_LOG | 
| 44 // *.pb.h files are generated at build-time by the protobuf compiler. | 50 // *.pb.h files are generated at build-time by the protobuf compiler. | 
| 51 RTC_PUSH_IGNORING_WUNDEF() | |
| 45 #ifdef WEBRTC_ANDROID_PLATFORM_BUILD | 52 #ifdef WEBRTC_ANDROID_PLATFORM_BUILD | 
| 46 #include "external/webrtc/webrtc/logging/rtc_event_log/rtc_event_log.pb.h" | 53 #include "external/webrtc/webrtc/logging/rtc_event_log/rtc_event_log.pb.h" | 
| 47 #else | 54 #else | 
| 48 #include "webrtc/logging/rtc_event_log/rtc_event_log.pb.h" | 55 #include "webrtc/logging/rtc_event_log/rtc_event_log.pb.h" | 
| 49 #endif | 56 #endif | 
| 57 RTC_POP_IGNORING_WUNDEF() | |
| 50 #endif | 58 #endif | 
| 51 | 59 | 
| 52 namespace webrtc { | 60 namespace webrtc { | 
| 53 | 61 | 
| 54 #ifdef ENABLE_RTC_EVENT_LOG | 62 #ifdef ENABLE_RTC_EVENT_LOG | 
| 55 | 63 | 
| 64 namespace { | |
| 65 const int kEventsInHistory = 10000; | |
| 66 | |
| 67 bool IsConfigEvent(const rtclog::Event& event) { | |
| 68 rtclog::Event_EventType event_type = event.type(); | |
| 69 return event_type == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT || | |
| 70 event_type == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT || | |
| 71 event_type == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT || | |
| 72 event_type == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT; | |
| 73 } | |
| 74 | |
| 75 // This class exists because C++11 doesn't allow transferring a unique_ptr to | |
| 76 // a lambda (a copy constructor is required). | |
| 
 
nisse-webrtc
2017/08/31 12:09:24
Could be formulated as a TODO item to remove the c
 
eladalon
2017/08/31 12:31:32
Done.
 
 | |
| 77 template <typename T> | |
| 78 class ResourceOwningTask final : public rtc::QueuedTask { | |
| 79 public: | |
| 80 ResourceOwningTask(std::unique_ptr<T> resource, | |
| 81 std::function<void(std::unique_ptr<T>)> handler) | |
| 82 : resource_(std::move(resource)), handler_(handler) {} | |
| 83 | |
| 84 bool Run() override { | |
| 85 handler_(std::move(resource_)); | |
| 86 return true; | |
| 87 } | |
| 88 | |
| 89 private: | |
| 90 std::unique_ptr<T> resource_; | |
| 91 std::function<void(std::unique_ptr<T>)> handler_; | |
| 92 }; | |
| 93 } // namespace | |
| 94 | |
| 56 class RtcEventLogImpl final : public RtcEventLog { | 95 class RtcEventLogImpl final : public RtcEventLog { | 
| 57 friend std::unique_ptr<RtcEventLog> RtcEventLog::Create(); | 96 friend std::unique_ptr<RtcEventLog> RtcEventLog::Create(); | 
| 58 | 97 | 
| 59 public: | 98 public: | 
| 60 ~RtcEventLogImpl() override; | 99 ~RtcEventLogImpl() override; | 
| 61 | 100 | 
| 62 bool StartLogging(const std::string& file_name, | 101 bool StartLogging(const std::string& file_name, | 
| 63 int64_t max_size_bytes) override; | 102 int64_t max_size_bytes) override; | 
| 64 bool StartLogging(rtc::PlatformFile platform_file, | 103 bool StartLogging(rtc::PlatformFile platform_file, | 
| 65 int64_t max_size_bytes) override; | 104 int64_t max_size_bytes) override; | 
| (...skipping 22 matching lines...) Expand all Loading... | |
| 88 const AudioEncoderRuntimeConfig& config) override; | 127 const AudioEncoderRuntimeConfig& config) override; | 
| 89 void LogProbeClusterCreated(int id, | 128 void LogProbeClusterCreated(int id, | 
| 90 int bitrate_bps, | 129 int bitrate_bps, | 
| 91 int min_probes, | 130 int min_probes, | 
| 92 int min_bytes) override; | 131 int min_bytes) override; | 
| 93 void LogProbeResultSuccess(int id, int bitrate_bps) override; | 132 void LogProbeResultSuccess(int id, int bitrate_bps) override; | 
| 94 void LogProbeResultFailure(int id, | 133 void LogProbeResultFailure(int id, | 
| 95 ProbeFailureReason failure_reason) override; | 134 ProbeFailureReason failure_reason) override; | 
| 96 | 135 | 
| 97 private: | 136 private: | 
| 98 // Private constructor to ensure that creation is done by RtcEventLog::Create. | 137 void StartLoggingInternal(std::unique_ptr<FileWrapper> file, | 
| 99 RtcEventLogImpl(); | 138 int64_t max_size_bytes); | 
| 139 | |
| 140 RtcEventLogImpl(); // Creation is done by RtcEventLog::Create. | |
| 100 | 141 | 
| 101 void StoreEvent(std::unique_ptr<rtclog::Event> event); | 142 void StoreEvent(std::unique_ptr<rtclog::Event> event); | 
| 102 void LogProbeResult(int id, | 143 void LogProbeResult(int id, | 
| 103 rtclog::BweProbeResult::ResultType result, | 144 rtclog::BweProbeResult::ResultType result, | 
| 104 int bitrate_bps); | 145 int bitrate_bps); | 
| 105 | 146 | 
| 106 static volatile int log_count_; | 147 // Appends an event to the output protobuf string, returning true on success. | 
| 148 // Fails and returns false in case the limit out output size prevents the | |
| 
 
nisse-webrtc
2017/08/31 12:09:24
Sorry if that was my typo, but it should be "on",
 
eladalon
2017/08/31 12:31:32
Done.
 
 | |
| 149 // event from being added; in this case, the output string is left unchanged. | |
| 150 bool AppendEventToString(rtclog::Event* event, | |
| 151 ProtoString* output_string) RTC_WARN_UNUSED_RESULT; | |
| 107 | 152 | 
| 108 // Message queue for passing control messages to the logging thread. | 153 void LogToMemory(std::unique_ptr<rtclog::Event> event); | 
| 109 SwapQueue<RtcEventLogHelperThread::ControlMessage> message_queue_; | |
| 110 | 154 | 
| 111 // Message queue for passing events to the logging thread. | 155 void StartLogFile(); | 
| 112 SwapQueue<std::unique_ptr<rtclog::Event> > event_queue_; | 156 void LogToFile(std::unique_ptr<rtclog::Event> event); | 
| 157 void StopLogFile(int64_t stop_time); | |
| 113 | 158 | 
| 114 RtcEventLogHelperThread helper_thread_; | 159 // Observe a limit on the number of concurrent logs, so as not to run into | 
| 115 rtc::ThreadChecker thread_checker_; | 160 // OS-imposed limits on open files and/or threads/task-queues. | 
| 161 // TODO(eladalon): Known issue - there's a race over |log_count_|. | |
| 162 static std::atomic<int> log_count_; | |
| 163 | |
| 164 rtc::SequencedTaskChecker worker_sequence_checker_; | |
| 165 rtc::SequencedTaskChecker owner_sequence_checker_; | |
| 166 | |
| 167 // History containing all past configuration events. | |
| 168 std::vector<std::unique_ptr<rtclog::Event>> config_history_ | |
| 169 GUARDED_BY(worker_sequence_checker_); | |
| 170 | |
| 171 // History containing the most recent (non-configuration) events (~ 10 s). | |
| 172 std::deque<std::unique_ptr<rtclog::Event>> history_ | |
| 173 GUARDED_BY(worker_sequence_checker_); | |
| 174 | |
| 175 std::unique_ptr<FileWrapper> file_ GUARDED_BY(worker_sequence_checker_); | |
| 176 | |
| 177 size_t max_size_bytes_ GUARDED_BY(worker_sequence_checker_); | |
| 178 size_t written_bytes_ GUARDED_BY(worker_sequence_checker_); | |
| 179 | |
| 180 // Keep this last to ensure it destructs first, or else tasks living on the | |
| 181 // queue might access other members after they've been torn down. | |
| 182 rtc::TaskQueue task_queue_; | |
| 116 | 183 | 
| 117 RTC_DISALLOW_COPY_AND_ASSIGN(RtcEventLogImpl); | 184 RTC_DISALLOW_COPY_AND_ASSIGN(RtcEventLogImpl); | 
| 118 }; | 185 }; | 
| 119 | 186 | 
| 120 namespace { | 187 namespace { | 
| 121 // The functions in this namespace convert enums from the runtime format | 188 // The functions in this namespace convert enums from the runtime format | 
| 122 // that the rest of the WebRtc project can use, to the corresponding | 189 // that the rest of the WebRtc project can use, to the corresponding | 
| 123 // serialized enum which is defined by the protobuf. | 190 // serialized enum which is defined by the protobuf. | 
| 124 | 191 | 
| 125 rtclog::VideoReceiveConfig_RtcpMode ConvertRtcpMode(RtcpMode rtcp_mode) { | 192 rtclog::VideoReceiveConfig_RtcpMode ConvertRtcpMode(RtcpMode rtcp_mode) { | 
| (...skipping 31 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
| 157 return rtclog::BweProbeResult::INVALID_SEND_RECEIVE_INTERVAL; | 224 return rtclog::BweProbeResult::INVALID_SEND_RECEIVE_INTERVAL; | 
| 158 case kInvalidSendReceiveRatio: | 225 case kInvalidSendReceiveRatio: | 
| 159 return rtclog::BweProbeResult::INVALID_SEND_RECEIVE_RATIO; | 226 return rtclog::BweProbeResult::INVALID_SEND_RECEIVE_RATIO; | 
| 160 case kTimeout: | 227 case kTimeout: | 
| 161 return rtclog::BweProbeResult::TIMEOUT; | 228 return rtclog::BweProbeResult::TIMEOUT; | 
| 162 } | 229 } | 
| 163 RTC_NOTREACHED(); | 230 RTC_NOTREACHED(); | 
| 164 return rtclog::BweProbeResult::SUCCESS; | 231 return rtclog::BweProbeResult::SUCCESS; | 
| 165 } | 232 } | 
| 166 | 233 | 
| 167 // The RTP and RTCP buffers reserve space for twice the expected number of | |
| 168 // sent packets because they also contain received packets. | |
| 169 static const int kEventsPerSecond = 1000; | |
| 170 static const int kControlMessagesPerSecond = 10; | |
| 171 } // namespace | 234 } // namespace | 
| 172 | 235 | 
| 173 volatile int RtcEventLogImpl::log_count_ = 0; | 236 std::atomic<int> RtcEventLogImpl::log_count_(0); | 
| 174 | 237 | 
| 175 // RtcEventLogImpl member functions. | |
| 176 RtcEventLogImpl::RtcEventLogImpl() | 238 RtcEventLogImpl::RtcEventLogImpl() | 
| 177 // Allocate buffers for roughly one second of history. | 239 : file_(FileWrapper::Create()), | 
| 178 : message_queue_(kControlMessagesPerSecond), | 240 max_size_bytes_(std::numeric_limits<decltype(max_size_bytes_)>::max()), | 
| 179 event_queue_(kEventsPerSecond), | 241 written_bytes_(0), | 
| 180 helper_thread_(&message_queue_, &event_queue_), | 242 task_queue_("rtc_event_log") { | 
| 181 thread_checker_() { | 243 worker_sequence_checker_.Detach(); | 
| 182 thread_checker_.DetachFromThread(); | |
| 183 } | 244 } | 
| 184 | 245 | 
| 185 RtcEventLogImpl::~RtcEventLogImpl() { | 246 RtcEventLogImpl::~RtcEventLogImpl() { | 
| 186 // The RtcEventLogHelperThread destructor closes the file | 247 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); | 
| 187 // and waits for the thread to terminate. | 248 | 
| 188 int count = rtc::AtomicOps::Decrement(&RtcEventLogImpl::log_count_); | 249 // If we're logging to the file, this will stop that. Blocking function. | 
| 250 StopLogging(); | |
| 251 | |
| 252 int count = std::atomic_fetch_sub(&RtcEventLogImpl::log_count_, 1) - 1; | |
| 189 RTC_DCHECK_GE(count, 0); | 253 RTC_DCHECK_GE(count, 0); | 
| 190 } | 254 } | 
| 191 | 255 | 
| 192 bool RtcEventLogImpl::StartLogging(const std::string& file_name, | 256 bool RtcEventLogImpl::StartLogging(const std::string& file_name, | 
| 193 int64_t max_size_bytes) { | 257 int64_t max_size_bytes) { | 
| 194 RTC_DCHECK(thread_checker_.CalledOnValidThread()); | 258 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); | 
| 195 RtcEventLogHelperThread::ControlMessage message; | 259 | 
| 196 message.message_type = RtcEventLogHelperThread::ControlMessage::START_FILE; | 260 auto file = rtc::WrapUnique<FileWrapper>(FileWrapper::Create()); | 
| 197 message.max_size_bytes = max_size_bytes <= 0 | 261 if (!file->OpenFile(file_name.c_str(), false)) { | 
| 198 ? std::numeric_limits<int64_t>::max() | |
| 199 : max_size_bytes; | |
| 200 message.start_time = rtc::TimeMicros(); | |
| 201 message.stop_time = std::numeric_limits<int64_t>::max(); | |
| 202 message.file.reset(FileWrapper::Create()); | |
| 203 if (!message.file->OpenFile(file_name.c_str(), false)) { | |
| 204 LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; | 262 LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; | 
| 205 return false; | 263 return false; | 
| 206 } | 264 } | 
| 207 if (!message_queue_.Insert(&message)) { | 265 | 
| 208 LOG(LS_ERROR) << "Message queue full. Can't start logging."; | 266 StartLoggingInternal(std::move(file), max_size_bytes); | 
| 209 return false; | 267 | 
| 210 } | |
| 211 helper_thread_.SignalNewEvent(); | |
| 212 LOG(LS_INFO) << "Starting WebRTC event log."; | |
| 213 return true; | 268 return true; | 
| 214 } | 269 } | 
| 215 | 270 | 
| 216 bool RtcEventLogImpl::StartLogging(rtc::PlatformFile platform_file, | 271 bool RtcEventLogImpl::StartLogging(rtc::PlatformFile platform_file, | 
| 217 int64_t max_size_bytes) { | 272 int64_t max_size_bytes) { | 
| 218 RTC_DCHECK(thread_checker_.CalledOnValidThread()); | 273 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); | 
| 219 RtcEventLogHelperThread::ControlMessage message; | 274 | 
| 220 message.message_type = RtcEventLogHelperThread::ControlMessage::START_FILE; | 275 auto file = rtc::WrapUnique<FileWrapper>(FileWrapper::Create()); | 
| 
 
nisse-webrtc
2017/08/31 12:09:24
I take it this a correct use of WrapUnique, workin
 
eladalon
2017/08/31 12:31:32
Yes - unlike the other use of WrapUnique, which wa
 
 | |
| 221 message.max_size_bytes = max_size_bytes <= 0 | |
| 222 ? std::numeric_limits<int64_t>::max() | |
| 223 : max_size_bytes; | |
| 224 message.start_time = rtc::TimeMicros(); | |
| 225 message.stop_time = std::numeric_limits<int64_t>::max(); | |
| 226 message.file.reset(FileWrapper::Create()); | |
| 227 FILE* file_handle = rtc::FdopenPlatformFileForWriting(platform_file); | 276 FILE* file_handle = rtc::FdopenPlatformFileForWriting(platform_file); | 
| 228 if (!file_handle) { | 277 if (!file_handle) { | 
| 229 LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; | 278 LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; | 
| 230 // Even though we failed to open a FILE*, the platform_file is still open | 279 // Even though we failed to open a FILE*, the platform_file is still open | 
| 231 // and needs to be closed. | 280 // and needs to be closed. | 
| 232 if (!rtc::ClosePlatformFile(platform_file)) { | 281 if (!rtc::ClosePlatformFile(platform_file)) { | 
| 233 LOG(LS_ERROR) << "Can't close file."; | 282 LOG(LS_ERROR) << "Can't close file."; | 
| 234 } | 283 } | 
| 235 return false; | 284 return false; | 
| 236 } | 285 } | 
| 237 if (!message.file->OpenFromFileHandle(file_handle)) { | 286 if (!file->OpenFromFileHandle(file_handle)) { | 
| 238 LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; | 287 LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; | 
| 239 return false; | 288 return false; | 
| 240 } | 289 } | 
| 241 if (!message_queue_.Insert(&message)) { | 290 | 
| 242 LOG(LS_ERROR) << "Message queue full. Can't start logging."; | 291 StartLoggingInternal(std::move(file), max_size_bytes); | 
| 243 return false; | 292 | 
| 244 } | |
| 245 helper_thread_.SignalNewEvent(); | |
| 246 LOG(LS_INFO) << "Starting WebRTC event log."; | |
| 247 return true; | 293 return true; | 
| 248 } | 294 } | 
| 249 | 295 | 
| 250 void RtcEventLogImpl::StopLogging() { | 296 void RtcEventLogImpl::StopLogging() { | 
| 251 RTC_DCHECK(thread_checker_.CalledOnValidThread()); | 297 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); | 
| 252 RtcEventLogHelperThread::ControlMessage message; | 298 | 
| 253 message.message_type = RtcEventLogHelperThread::ControlMessage::STOP_FILE; | |
| 254 message.stop_time = rtc::TimeMicros(); | |
| 255 while (!message_queue_.Insert(&message)) { | |
| 256 // TODO(terelius): We would like to have a blocking Insert function in the | |
| 257 // SwapQueue, but for the time being we will just clear any previous | |
| 258 // messages. | |
| 259 // Since StopLogging waits for the thread, it is essential that we don't | |
| 260 // clear any STOP_FILE messages. To ensure that there is only one call at a | |
| 261 // time, we require that all calls to StopLogging are made on the same | |
| 262 // thread. | |
| 263 LOG(LS_ERROR) << "Message queue full. Clearing queue to stop logging."; | |
| 264 message_queue_.Clear(); | |
| 265 } | |
| 266 LOG(LS_INFO) << "Stopping WebRTC event log."; | 299 LOG(LS_INFO) << "Stopping WebRTC event log."; | 
| 267 helper_thread_.WaitForFileFinished(); | 300 | 
| 301 const int64_t stop_time = rtc::TimeMicros(); | |
| 302 | |
| 303 task_queue_.PostTask([this, stop_time]() { | |
| 304 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 305 if (file_->is_open()) { | |
| 306 StopLogFile(stop_time); | |
| 307 } | |
| 308 }); | |
| 309 | |
| 310 // Wait for an indication that the previous task, which stops the log file, | |
| 311 // has been executed to completion. | |
| 312 rtc::Event file_finished(true, false); | |
| 313 task_queue_.PostTask([this, &file_finished]() { | |
| 314 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 315 file_finished.Set(); | |
| 316 }); | |
| 317 file_finished.Wait(rtc::Event::kForever); | |
| 318 | |
| 319 LOG(LS_INFO) << "WebRTC event log successfully stopped."; | |
| 268 } | 320 } | 
| 269 | 321 | 
| 270 void RtcEventLogImpl::LogVideoReceiveStreamConfig( | 322 void RtcEventLogImpl::LogVideoReceiveStreamConfig( | 
| 271 const rtclog::StreamConfig& config) { | 323 const rtclog::StreamConfig& config) { | 
| 272 std::unique_ptr<rtclog::Event> event(new rtclog::Event()); | 324 std::unique_ptr<rtclog::Event> event(new rtclog::Event()); | 
| 273 event->set_timestamp_us(rtc::TimeMicros()); | 325 event->set_timestamp_us(rtc::TimeMicros()); | 
| 274 event->set_type(rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT); | 326 event->set_type(rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT); | 
| 275 | 327 | 
| 276 rtclog::VideoReceiveConfig* receiver_config = | 328 rtclog::VideoReceiveConfig* receiver_config = | 
| 277 event->mutable_video_receiver_config(); | 329 event->mutable_video_receiver_config(); | 
| (...skipping 280 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
| 558 event->set_type(rtclog::Event::BWE_PROBE_RESULT_EVENT); | 610 event->set_type(rtclog::Event::BWE_PROBE_RESULT_EVENT); | 
| 559 | 611 | 
| 560 auto probe_result = event->mutable_probe_result(); | 612 auto probe_result = event->mutable_probe_result(); | 
| 561 probe_result->set_id(id); | 613 probe_result->set_id(id); | 
| 562 probe_result->set_result(result); | 614 probe_result->set_result(result); | 
| 563 if (result == rtclog::BweProbeResult::SUCCESS) | 615 if (result == rtclog::BweProbeResult::SUCCESS) | 
| 564 probe_result->set_bitrate_bps(bitrate_bps); | 616 probe_result->set_bitrate_bps(bitrate_bps); | 
| 565 StoreEvent(std::move(event)); | 617 StoreEvent(std::move(event)); | 
| 566 } | 618 } | 
| 567 | 619 | 
| 620 void RtcEventLogImpl::StartLoggingInternal(std::unique_ptr<FileWrapper> file, | |
| 621 int64_t max_size_bytes) { | |
| 622 LOG(LS_INFO) << "Starting WebRTC event log."; | |
| 623 | |
| 624 max_size_bytes = (max_size_bytes <= 0) ? std::numeric_limits<int64_t>::max() | |
| 625 : max_size_bytes; | |
| 626 auto file_handler = [this, | |
| 627 max_size_bytes](std::unique_ptr<FileWrapper> file) { | |
| 628 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 629 if (!file_->is_open()) { | |
| 630 max_size_bytes_ = max_size_bytes; | |
| 631 file_ = std::move(file); | |
| 632 StartLogFile(); | |
| 633 } else { | |
| 634 // Already started. Ignore message and close file handle. | |
| 635 file->CloseFile(); | |
| 636 } | |
| 637 }; | |
| 638 task_queue_.PostTask(rtc::MakeUnique<ResourceOwningTask<FileWrapper>>( | |
| 639 std::move(file), file_handler)); | |
| 640 } | |
| 641 | |
| 568 void RtcEventLogImpl::StoreEvent(std::unique_ptr<rtclog::Event> event) { | 642 void RtcEventLogImpl::StoreEvent(std::unique_ptr<rtclog::Event> event) { | 
| 569 RTC_DCHECK(event.get() != nullptr); | 643 RTC_DCHECK(event); | 
| 570 if (!event_queue_.Insert(&event)) { | 644 | 
| 571 LOG(LS_ERROR) << "WebRTC event log queue full. Dropping event."; | 645 auto event_handler = [this](std::unique_ptr<rtclog::Event> rtclog_event) { | 
| 646 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 647 if (file_->is_open()) { | |
| 648 LogToFile(std::move(rtclog_event)); | |
| 649 } else { | |
| 650 LogToMemory(std::move(rtclog_event)); | |
| 651 } | |
| 652 }; | |
| 653 | |
| 654 task_queue_.PostTask(rtc::MakeUnique<ResourceOwningTask<rtclog::Event>>( | |
| 
 
nisse-webrtc
2017/08/31 12:09:24
I think this looks nicer. Thanks.
 
eladalon
2017/08/31 12:31:32
Once we've added the version of PostTask() that al
 
 | |
| 655 std::move(event), event_handler)); | |
| 656 } | |
| 657 | |
| 658 bool RtcEventLogImpl::AppendEventToString(rtclog::Event* event, | |
| 659 ProtoString* output_string) { | |
| 660 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 661 | |
| 662 // Even though we're only serializing a single event during this call, what | |
| 663 // we intend to get is a list of events, with a tag and length preceding | |
| 664 // each actual event. To produce that, we serialize a list of a single event. | |
| 665 // If we later serialize additional events, the resulting ProtoString will | |
| 666 // be a proper concatenation of all those events. | |
| 667 | |
| 668 rtclog::EventStream event_stream; | |
| 669 event_stream.add_stream(); | |
| 670 | |
| 671 // As a tweak, we swap the new event into the event-stream, write that to | |
| 672 // file, then swap back. This saves on some copying. | |
| 673 rtclog::Event* output_event = event_stream.mutable_stream(0); | |
| 674 output_event->Swap(event); | |
| 675 | |
| 676 bool appended; | |
| 677 size_t potential_new_size = | |
| 678 written_bytes_ + output_string->size() + event_stream.ByteSize(); | |
| 679 if (potential_new_size <= max_size_bytes_) { | |
| 680 event_stream.AppendToString(output_string); | |
| 681 appended = true; | |
| 682 } else { | |
| 683 appended = false; | |
| 572 } | 684 } | 
| 573 helper_thread_.SignalNewEvent(); | 685 | 
| 686 // When the function returns, the original Event will be unchanged. | |
| 687 output_event->Swap(event); | |
| 688 | |
| 689 return appended; | |
| 690 } | |
| 691 | |
| 692 void RtcEventLogImpl::LogToMemory(std::unique_ptr<rtclog::Event> event) { | |
| 693 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 694 RTC_DCHECK(!file_->is_open()); | |
| 695 | |
| 696 if (IsConfigEvent(*event.get())) { | |
| 697 config_history_.push_back(std::move(event)); | |
| 698 } else { | |
| 699 history_.push_back(std::move(event)); | |
| 700 if (history_.size() > kEventsInHistory) { | |
| 701 history_.pop_front(); | |
| 702 } | |
| 703 } | |
| 704 } | |
| 705 | |
| 706 void RtcEventLogImpl::StartLogFile() { | |
| 707 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 708 RTC_DCHECK(file_->is_open()); | |
| 709 | |
| 710 ProtoString output_string; | |
| 711 | |
| 712 // Create and serialize the LOG_START event. | |
| 713 // The timestamp used will correspond to when logging has started. The log | |
| 714 // may contain events earlier than the LOG_START event. (In general, the | |
| 715 // timestamps in the log are not monotonic.) | |
| 716 rtclog::Event start_event; | |
| 717 start_event.set_timestamp_us(rtc::TimeMicros()); | |
| 718 start_event.set_type(rtclog::Event::LOG_START); | |
| 719 bool appended = AppendEventToString(&start_event, &output_string); | |
| 720 | |
| 721 // Serialize the config information for all old streams, including streams | |
| 722 // which were already logged to previous files. | |
| 723 for (auto& event : config_history_) { | |
| 724 if (!appended) { | |
| 725 break; | |
| 726 } | |
| 727 appended = AppendEventToString(event.get(), &output_string); | |
| 728 } | |
| 729 | |
| 730 // Serialize the events in the event queue. | |
| 731 while (appended && !history_.empty()) { | |
| 732 appended = AppendEventToString(history_.front().get(), &output_string); | |
| 733 if (appended) { | |
| 734 // Known issue - if writing to the file fails, these events will have | |
| 735 // been lost. If we try to open a new file, these events will be missing | |
| 736 // from it. | |
| 737 history_.pop_front(); | |
| 738 } | |
| 739 } | |
| 740 | |
| 741 // Write to file. | |
| 742 if (!file_->Write(output_string.data(), output_string.size())) { | |
| 743 LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; | |
| 744 // The current FileWrapper implementation closes the file on error. | |
| 745 RTC_DCHECK(!file_->is_open()); | |
| 746 return; | |
| 747 } | |
| 748 written_bytes_ += output_string.size(); | |
| 749 | |
| 750 if (!appended) { | |
| 751 RTC_DCHECK(file_->is_open()); | |
| 752 StopLogFile(rtc::TimeMicros()); | |
| 753 } | |
| 754 } | |
| 755 | |
| 756 void RtcEventLogImpl::LogToFile(std::unique_ptr<rtclog::Event> event) { | |
| 757 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 758 RTC_DCHECK(file_->is_open()); | |
| 759 | |
| 760 ProtoString output_string; | |
| 761 | |
| 762 bool appended = AppendEventToString(event.get(), &output_string); | |
| 763 | |
| 764 if (IsConfigEvent(*event.get())) { | |
| 765 config_history_.push_back(std::move(event)); | |
| 766 } | |
| 767 | |
| 768 if (!appended) { | |
| 769 RTC_DCHECK(file_->is_open()); | |
| 770 history_.push_back(std::move(event)); | |
| 771 StopLogFile(rtc::TimeMicros()); | |
| 772 return; | |
| 773 } | |
| 774 | |
| 775 // Write string to file. | |
| 776 if (file_->Write(output_string.data(), output_string.size())) { | |
| 777 written_bytes_ += output_string.size(); | |
| 778 } else { | |
| 779 LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; | |
| 780 // The current FileWrapper implementation closes the file on error. | |
| 781 RTC_DCHECK(!file_->is_open()); | |
| 782 } | |
| 783 } | |
| 784 | |
| 785 void RtcEventLogImpl::StopLogFile(int64_t stop_time) { | |
| 786 RTC_DCHECK_CALLED_SEQUENTIALLY(&worker_sequence_checker_); | |
| 787 RTC_DCHECK(file_->is_open()); | |
| 788 | |
| 789 ProtoString output_string; | |
| 790 | |
| 791 rtclog::Event end_event; | |
| 792 end_event.set_timestamp_us(stop_time); | |
| 793 end_event.set_type(rtclog::Event::LOG_END); | |
| 794 bool appended = AppendEventToString(&end_event, &output_string); | |
| 795 | |
| 796 if (appended) { | |
| 797 if (!file_->Write(output_string.data(), output_string.size())) { | |
| 798 LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; | |
| 799 // The current FileWrapper implementation closes the file on error. | |
| 800 RTC_DCHECK(!file_->is_open()); | |
| 801 } | |
| 802 written_bytes_ += output_string.size(); | |
| 803 } | |
| 804 | |
| 805 max_size_bytes_ = std::numeric_limits<int64_t>::max(); | |
| 806 written_bytes_ = 0; | |
| 807 | |
| 808 file_->CloseFile(); | |
| 809 RTC_DCHECK(!file_->is_open()); | |
| 574 } | 810 } | 
| 575 | 811 | 
| 576 bool RtcEventLog::ParseRtcEventLog(const std::string& file_name, | 812 bool RtcEventLog::ParseRtcEventLog(const std::string& file_name, | 
| 577 rtclog::EventStream* result) { | 813 rtclog::EventStream* result) { | 
| 578 char tmp_buffer[1024]; | 814 char tmp_buffer[1024]; | 
| 579 int bytes_read = 0; | 815 int bytes_read = 0; | 
| 580 std::unique_ptr<FileWrapper> dump_file(FileWrapper::Create()); | 816 std::unique_ptr<FileWrapper> dump_file(FileWrapper::Create()); | 
| 581 if (!dump_file->OpenFile(file_name.c_str(), true)) { | 817 if (!dump_file->OpenFile(file_name.c_str(), true)) { | 
| 582 return false; | 818 return false; | 
| 583 } | 819 } | 
| 584 ProtoString dump_buffer; | 820 ProtoString dump_buffer; | 
| 585 while ((bytes_read = dump_file->Read(tmp_buffer, sizeof(tmp_buffer))) > 0) { | 821 while ((bytes_read = dump_file->Read(tmp_buffer, sizeof(tmp_buffer))) > 0) { | 
| 586 dump_buffer.append(tmp_buffer, bytes_read); | 822 dump_buffer.append(tmp_buffer, bytes_read); | 
| 587 } | 823 } | 
| 588 dump_file->CloseFile(); | 824 dump_file->CloseFile(); | 
| 589 return result->ParseFromString(dump_buffer); | 825 return result->ParseFromString(dump_buffer); | 
| 590 } | 826 } | 
| 591 | 827 | 
| 592 #endif // ENABLE_RTC_EVENT_LOG | 828 #endif // ENABLE_RTC_EVENT_LOG | 
| 593 | 829 | 
| 594 // RtcEventLog member functions. | 830 // RtcEventLog member functions. | 
| 595 std::unique_ptr<RtcEventLog> RtcEventLog::Create() { | 831 std::unique_ptr<RtcEventLog> RtcEventLog::Create() { | 
| 596 #ifdef ENABLE_RTC_EVENT_LOG | 832 #ifdef ENABLE_RTC_EVENT_LOG | 
| 833 // TODO(eladalon): Known issue - there's a race over |log_count_| here. | |
| 597 constexpr int kMaxLogCount = 5; | 834 constexpr int kMaxLogCount = 5; | 
| 598 int count = rtc::AtomicOps::Increment(&RtcEventLogImpl::log_count_); | 835 int count = 1 + std::atomic_fetch_add(&RtcEventLogImpl::log_count_, 1); | 
| 599 if (count > kMaxLogCount) { | 836 if (count > kMaxLogCount) { | 
| 600 LOG(LS_WARNING) << "Denied creation of additional WebRTC event logs. " | 837 LOG(LS_WARNING) << "Denied creation of additional WebRTC event logs. " | 
| 601 << count - 1 << " logs open already."; | 838 << count - 1 << " logs open already."; | 
| 602 rtc::AtomicOps::Decrement(&RtcEventLogImpl::log_count_); | 839 std::atomic_fetch_sub(&RtcEventLogImpl::log_count_, 1); | 
| 603 return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); | 840 return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); | 
| 604 } | 841 } | 
| 605 return std::unique_ptr<RtcEventLog>(new RtcEventLogImpl()); | 842 return std::unique_ptr<RtcEventLog>(new RtcEventLogImpl()); | 
| 606 #else | 843 #else | 
| 607 return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); | 844 return CreateNull(); | 
| 608 #endif // ENABLE_RTC_EVENT_LOG | 845 #endif // ENABLE_RTC_EVENT_LOG | 
| 609 } | 846 } | 
| 610 | 847 | 
| 611 std::unique_ptr<RtcEventLog> RtcEventLog::CreateNull() { | 848 std::unique_ptr<RtcEventLog> RtcEventLog::CreateNull() { | 
| 612 return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); | 849 return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); | 
| 613 } | 850 } | 
| 614 | 851 | 
| 615 } // namespace webrtc | 852 } // namespace webrtc | 
| OLD | NEW |