1/* 2 * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. 3 * 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 6 * tree. An additional intellectual property rights grant can be found 7 * in the file PATENTS. All contributing project authors may 8 * be found in the AUTHORS file in the root of the source tree. 9 */ 10#include "webrtc/base/event_tracer.h" 11 12#include <inttypes.h> 13 14#include <vector> 15 16#include "webrtc/base/checks.h" 17#include "webrtc/base/criticalsection.h" 18#include "webrtc/base/event.h" 19#include "webrtc/base/logging.h" 20#include "webrtc/base/platform_thread.h" 21#include "webrtc/base/timeutils.h" 22#include "webrtc/base/trace_event.h" 23 24namespace webrtc { 25 26namespace { 27 28GetCategoryEnabledPtr g_get_category_enabled_ptr = nullptr; 29AddTraceEventPtr g_add_trace_event_ptr = nullptr; 30 31} // namespace 32 33void SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr, 34 AddTraceEventPtr add_trace_event_ptr) { 35 g_get_category_enabled_ptr = get_category_enabled_ptr; 36 g_add_trace_event_ptr = add_trace_event_ptr; 37} 38 39const unsigned char* EventTracer::GetCategoryEnabled(const char* name) { 40 if (g_get_category_enabled_ptr) 41 return g_get_category_enabled_ptr(name); 42 43 // A string with null terminator means category is disabled. 44 return reinterpret_cast<const unsigned char*>("\0"); 45} 46 47// Arguments to this function (phase, etc.) are as defined in 48// webrtc/base/trace_event.h. 49void EventTracer::AddTraceEvent(char phase, 50 const unsigned char* category_enabled, 51 const char* name, 52 unsigned long long id, 53 int num_args, 54 const char** arg_names, 55 const unsigned char* arg_types, 56 const unsigned long long* arg_values, 57 unsigned char flags) { 58 if (g_add_trace_event_ptr) { 59 g_add_trace_event_ptr(phase, 60 category_enabled, 61 name, 62 id, 63 num_args, 64 arg_names, 65 arg_types, 66 arg_values, 67 flags); 68 } 69} 70 71} // namespace webrtc 72 73namespace rtc { 74namespace tracing { 75namespace { 76 77static bool EventTracingThreadFunc(void* params); 78 79// Atomic-int fast path for avoiding logging when disabled. 80static volatile int g_event_logging_active = 0; 81 82// TODO(pbos): Log metadata for all threads, etc. 83class EventLogger final { 84 public: 85 EventLogger() 86 : logging_thread_(EventTracingThreadFunc, this, "EventTracingThread"), 87 shutdown_event_(false, false) {} 88 ~EventLogger() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); } 89 90 void AddTraceEvent(const char* name, 91 const unsigned char* category_enabled, 92 char phase, 93 uint64_t timestamp, 94 int pid, 95 rtc::PlatformThreadId thread_id) { 96 rtc::CritScope lock(&crit_); 97 trace_events_.push_back( 98 {name, category_enabled, phase, timestamp, 1, thread_id}); 99 } 100 101// The TraceEvent format is documented here: 102// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview 103 void Log() { 104 RTC_DCHECK(output_file_); 105 static const int kLoggingIntervalMs = 100; 106 fprintf(output_file_, "{ \"traceEvents\": [\n"); 107 bool has_logged_event = false; 108 while (true) { 109 bool shutting_down = shutdown_event_.Wait(kLoggingIntervalMs); 110 std::vector<TraceEvent> events; 111 { 112 rtc::CritScope lock(&crit_); 113 trace_events_.swap(events); 114 } 115 for (const TraceEvent& e : events) { 116 fprintf(output_file_, 117 "%s{ \"name\": \"%s\"" 118 ", \"cat\": \"%s\"" 119 ", \"ph\": \"%c\"" 120 ", \"ts\": %" PRIu64 121 ", \"pid\": %d" 122#if defined(WEBRTC_WIN) 123 ", \"tid\": %lu" 124#else 125 ", \"tid\": %d" 126#endif // defined(WEBRTC_WIN) 127 "}\n", 128 has_logged_event ? "," : " ", e.name, e.category_enabled, 129 e.phase, e.timestamp, e.pid, e.tid); 130 has_logged_event = true; 131 } 132 if (shutting_down) 133 break; 134 } 135 fprintf(output_file_, "]}\n"); 136 if (output_file_owned_) 137 fclose(output_file_); 138 output_file_ = nullptr; 139 } 140 141 void Start(FILE* file, bool owned) { 142 RTC_DCHECK(file); 143 RTC_DCHECK(!output_file_); 144 output_file_ = file; 145 output_file_owned_ = owned; 146 { 147 rtc::CritScope lock(&crit_); 148 // Since the atomic fast-path for adding events to the queue can be 149 // bypassed while the logging thread is shutting down there may be some 150 // stale events in the queue, hence the vector needs to be cleared to not 151 // log events from a previous logging session (which may be days old). 152 trace_events_.clear(); 153 } 154 // Enable event logging (fast-path). This should be disabled since starting 155 // shouldn't be done twice. 156 RTC_CHECK_EQ(0, 157 rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 0, 1)); 158 159 // Finally start, everything should be set up now. 160 logging_thread_.Start(); 161 } 162 163 void Stop() { 164 // Try to stop. Abort if we're not currently logging. 165 if (rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 1, 0) == 0) 166 return; 167 168 // Wake up logging thread to finish writing. 169 shutdown_event_.Set(); 170 // Join the logging thread. 171 logging_thread_.Stop(); 172 } 173 174 private: 175 struct TraceEvent { 176 const char* name; 177 const unsigned char* category_enabled; 178 char phase; 179 uint64_t timestamp; 180 int pid; 181 rtc::PlatformThreadId tid; 182 }; 183 184 rtc::CriticalSection crit_; 185 std::vector<TraceEvent> trace_events_ GUARDED_BY(crit_); 186 rtc::PlatformThread logging_thread_; 187 rtc::Event shutdown_event_; 188 rtc::ThreadChecker thread_checker_; 189 FILE* output_file_ = nullptr; 190 bool output_file_owned_ = false; 191}; 192 193static bool EventTracingThreadFunc(void* params) { 194 static_cast<EventLogger*>(params)->Log(); 195 return true; 196} 197 198static EventLogger* volatile g_event_logger = nullptr; 199static const char* const kDisabledTracePrefix = TRACE_DISABLED_BY_DEFAULT(""); 200const unsigned char* InternalGetCategoryEnabled(const char* name) { 201 const char* prefix_ptr = &kDisabledTracePrefix[0]; 202 const char* name_ptr = name; 203 // Check whether name contains the default-disabled prefix. 204 while (*prefix_ptr == *name_ptr && *prefix_ptr != '\0') { 205 ++prefix_ptr; 206 ++name_ptr; 207 } 208 return reinterpret_cast<const unsigned char*>(*prefix_ptr == '\0' ? "" 209 : name); 210} 211 212void InternalAddTraceEvent(char phase, 213 const unsigned char* category_enabled, 214 const char* name, 215 unsigned long long id, 216 int num_args, 217 const char** arg_names, 218 const unsigned char* arg_types, 219 const unsigned long long* arg_values, 220 unsigned char flags) { 221 // Fast path for when event tracing is inactive. 222 if (rtc::AtomicOps::AcquireLoad(&g_event_logging_active) == 0) 223 return; 224 225 g_event_logger->AddTraceEvent(name, category_enabled, phase, 226 rtc::TimeMicros(), 1, rtc::CurrentThreadId()); 227} 228 229} // namespace 230 231void SetupInternalTracer() { 232 RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr( 233 &g_event_logger, static_cast<EventLogger*>(nullptr), 234 new EventLogger()) == nullptr); 235 g_event_logger = new EventLogger(); 236 webrtc::SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent); 237} 238 239void StartInternalCaptureToFile(FILE* file) { 240 g_event_logger->Start(file, false); 241} 242 243bool StartInternalCapture(const char* filename) { 244 FILE* file = fopen(filename, "w"); 245 if (!file) { 246 LOG(LS_ERROR) << "Failed to open trace file '" << filename 247 << "' for writing."; 248 return false; 249 } 250 g_event_logger->Start(file, true); 251 return true; 252} 253 254void StopInternalCapture() { 255 g_event_logger->Stop(); 256} 257 258void ShutdownInternalTracer() { 259 StopInternalCapture(); 260 EventLogger* old_logger = rtc::AtomicOps::AcquireLoadPtr(&g_event_logger); 261 RTC_DCHECK(old_logger); 262 RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr( 263 &g_event_logger, old_logger, 264 static_cast<EventLogger*>(nullptr)) == old_logger); 265 delete old_logger; 266 webrtc::SetupEventTracer(nullptr, nullptr); 267} 268 269} // namespace tracing 270} // namespace rtc 271