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 "rtc_base/event_tracer.h"
11
12 #include <inttypes.h>
13
14 #include <string>
15 #include <vector>
16
17 #include "rtc_base/checks.h"
18 #include "rtc_base/criticalsection.h"
19 #include "rtc_base/event.h"
20 #include "rtc_base/logging.h"
21 #include "rtc_base/platform_thread.h"
22 #include "rtc_base/stringutils.h"
23 #include "rtc_base/timeutils.h"
24 #include "rtc_base/trace_event.h"
25
26 // This is a guesstimate that should be enough in most cases.
27 static const size_t kEventLoggerArgsStrBufferInitialSize = 256;
28 static const size_t kTraceArgBufferLength = 32;
29
30 namespace webrtc {
31
32 namespace {
33
34 GetCategoryEnabledPtr g_get_category_enabled_ptr = nullptr;
35 AddTraceEventPtr g_add_trace_event_ptr = nullptr;
36
37 } // namespace
38
SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr,AddTraceEventPtr add_trace_event_ptr)39 void SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr,
40 AddTraceEventPtr add_trace_event_ptr) {
41 g_get_category_enabled_ptr = get_category_enabled_ptr;
42 g_add_trace_event_ptr = add_trace_event_ptr;
43 }
44
GetCategoryEnabled(const char * name)45 const unsigned char* EventTracer::GetCategoryEnabled(const char* name) {
46 if (g_get_category_enabled_ptr)
47 return g_get_category_enabled_ptr(name);
48
49 // A string with null terminator means category is disabled.
50 return reinterpret_cast<const unsigned char*>("\0");
51 }
52
53 // Arguments to this function (phase, etc.) are as defined in
54 // webrtc/rtc_base/trace_event.h.
AddTraceEvent(char phase,const unsigned char * category_enabled,const char * name,unsigned long long id,int num_args,const char ** arg_names,const unsigned char * arg_types,const unsigned long long * arg_values,unsigned char flags)55 void EventTracer::AddTraceEvent(char phase,
56 const unsigned char* category_enabled,
57 const char* name,
58 unsigned long long id,
59 int num_args,
60 const char** arg_names,
61 const unsigned char* arg_types,
62 const unsigned long long* arg_values,
63 unsigned char flags) {
64 if (g_add_trace_event_ptr) {
65 g_add_trace_event_ptr(phase,
66 category_enabled,
67 name,
68 id,
69 num_args,
70 arg_names,
71 arg_types,
72 arg_values,
73 flags);
74 }
75 }
76
77 } // namespace webrtc
78
79 namespace rtc {
80 namespace tracing {
81 namespace {
82
83 static void EventTracingThreadFunc(void* params);
84
85 // Atomic-int fast path for avoiding logging when disabled.
86 static volatile int g_event_logging_active = 0;
87
88 // TODO(pbos): Log metadata for all threads, etc.
89 class EventLogger final {
90 public:
EventLogger()91 EventLogger()
92 : logging_thread_(EventTracingThreadFunc,
93 this,
94 "EventTracingThread",
95 kLowPriority),
96 shutdown_event_(false, false) {}
~EventLogger()97 ~EventLogger() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); }
98
AddTraceEvent(const char * name,const unsigned char * category_enabled,char phase,int num_args,const char ** arg_names,const unsigned char * arg_types,const unsigned long long * arg_values,uint64_t timestamp,int pid,rtc::PlatformThreadId thread_id)99 void AddTraceEvent(const char* name,
100 const unsigned char* category_enabled,
101 char phase,
102 int num_args,
103 const char** arg_names,
104 const unsigned char* arg_types,
105 const unsigned long long* arg_values,
106 uint64_t timestamp,
107 int pid,
108 rtc::PlatformThreadId thread_id) {
109 std::vector<TraceArg> args(num_args);
110 for (int i = 0; i < num_args; ++i) {
111 TraceArg& arg = args[i];
112 arg.name = arg_names[i];
113 arg.type = arg_types[i];
114 arg.value.as_uint = arg_values[i];
115
116 // Value is a pointer to a temporary string, so we have to make a copy.
117 if (arg.type == TRACE_VALUE_TYPE_COPY_STRING) {
118 // Space for the string and for the terminating null character.
119 size_t str_length = strlen(arg.value.as_string) + 1;
120 char* str_copy = new char[str_length];
121 memcpy(str_copy, arg.value.as_string, str_length);
122 arg.value.as_string = str_copy;
123 }
124 }
125 rtc::CritScope lock(&crit_);
126 trace_events_.push_back(
127 {name, category_enabled, phase, args, timestamp, 1, thread_id});
128 }
129
130 // The TraceEvent format is documented here:
131 // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
Log()132 void Log() {
133 RTC_DCHECK(output_file_);
134 static const int kLoggingIntervalMs = 100;
135 fprintf(output_file_, "{ \"traceEvents\": [\n");
136 bool has_logged_event = false;
137 while (true) {
138 bool shutting_down = shutdown_event_.Wait(kLoggingIntervalMs);
139 std::vector<TraceEvent> events;
140 {
141 rtc::CritScope lock(&crit_);
142 trace_events_.swap(events);
143 }
144 std::string args_str;
145 args_str.reserve(kEventLoggerArgsStrBufferInitialSize);
146 for (TraceEvent& e : events) {
147 args_str.clear();
148 if (!e.args.empty()) {
149 args_str += ", \"args\": {";
150 bool is_first_argument = true;
151 for (TraceArg& arg : e.args) {
152 if (!is_first_argument)
153 args_str += ",";
154 is_first_argument = false;
155 args_str += " \"";
156 args_str += arg.name;
157 args_str += "\": ";
158 args_str += TraceArgValueAsString(arg);
159
160 // Delete our copy of the string.
161 if (arg.type == TRACE_VALUE_TYPE_COPY_STRING) {
162 delete[] arg.value.as_string;
163 arg.value.as_string = nullptr;
164 }
165 }
166 args_str += " }";
167 }
168 fprintf(output_file_,
169 "%s{ \"name\": \"%s\""
170 ", \"cat\": \"%s\""
171 ", \"ph\": \"%c\""
172 ", \"ts\": %" PRIu64
173 ", \"pid\": %d"
174 #if defined(WEBRTC_WIN)
175 ", \"tid\": %lu"
176 #else
177 ", \"tid\": %d"
178 #endif // defined(WEBRTC_WIN)
179 "%s"
180 "}\n",
181 has_logged_event ? "," : " ", e.name, e.category_enabled,
182 e.phase, e.timestamp, e.pid, e.tid, args_str.c_str());
183 has_logged_event = true;
184 }
185 if (shutting_down)
186 break;
187 }
188 fprintf(output_file_, "]}\n");
189 if (output_file_owned_)
190 fclose(output_file_);
191 output_file_ = nullptr;
192 }
193
Start(FILE * file,bool owned)194 void Start(FILE* file, bool owned) {
195 RTC_DCHECK(thread_checker_.CalledOnValidThread());
196 RTC_DCHECK(file);
197 RTC_DCHECK(!output_file_);
198 output_file_ = file;
199 output_file_owned_ = owned;
200 {
201 rtc::CritScope lock(&crit_);
202 // Since the atomic fast-path for adding events to the queue can be
203 // bypassed while the logging thread is shutting down there may be some
204 // stale events in the queue, hence the vector needs to be cleared to not
205 // log events from a previous logging session (which may be days old).
206 trace_events_.clear();
207 }
208 // Enable event logging (fast-path). This should be disabled since starting
209 // shouldn't be done twice.
210 RTC_CHECK_EQ(0,
211 rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 0, 1));
212
213 // Finally start, everything should be set up now.
214 logging_thread_.Start();
215 TRACE_EVENT_INSTANT0("webrtc", "EventLogger::Start");
216 }
217
Stop()218 void Stop() {
219 RTC_DCHECK(thread_checker_.CalledOnValidThread());
220 TRACE_EVENT_INSTANT0("webrtc", "EventLogger::Stop");
221 // Try to stop. Abort if we're not currently logging.
222 if (rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 1, 0) == 0)
223 return;
224
225 // Wake up logging thread to finish writing.
226 shutdown_event_.Set();
227 // Join the logging thread.
228 logging_thread_.Stop();
229 }
230
231 private:
232 struct TraceArg {
233 const char* name;
234 unsigned char type;
235 // Copied from webrtc/rtc_base/trace_event.h TraceValueUnion.
236 union TraceArgValue {
237 bool as_bool;
238 unsigned long long as_uint;
239 long long as_int;
240 double as_double;
241 const void* as_pointer;
242 const char* as_string;
243 } value;
244
245 // Assert that the size of the union is equal to the size of the as_uint
246 // field since we are assigning to arbitrary types using it.
247 static_assert(sizeof(TraceArgValue) == sizeof(unsigned long long),
248 "Size of TraceArg value union is not equal to the size of "
249 "the uint field of that union.");
250 };
251
252 struct TraceEvent {
253 const char* name;
254 const unsigned char* category_enabled;
255 char phase;
256 std::vector<TraceArg> args;
257 uint64_t timestamp;
258 int pid;
259 rtc::PlatformThreadId tid;
260 };
261
TraceArgValueAsString(TraceArg arg)262 static std::string TraceArgValueAsString(TraceArg arg) {
263 std::string output;
264
265 if (arg.type == TRACE_VALUE_TYPE_STRING ||
266 arg.type == TRACE_VALUE_TYPE_COPY_STRING) {
267 // Space for every character to be an espaced character + two for
268 // quatation marks.
269 output.reserve(strlen(arg.value.as_string) * 2 + 2);
270 output += '\"';
271 const char* c = arg.value.as_string;
272 do {
273 if (*c == '"' || *c == '\\') {
274 output += '\\';
275 output += *c;
276 } else {
277 output += *c;
278 }
279 } while (*++c);
280 output += '\"';
281 } else {
282 output.resize(kTraceArgBufferLength);
283 size_t print_length = 0;
284 switch (arg.type) {
285 case TRACE_VALUE_TYPE_BOOL:
286 if (arg.value.as_bool) {
287 strcpy(&output[0], "true");
288 print_length = 4;
289 } else {
290 strcpy(&output[0], "false");
291 print_length = 5;
292 }
293 break;
294 case TRACE_VALUE_TYPE_UINT:
295 print_length = sprintfn(&output[0], kTraceArgBufferLength, "%llu",
296 arg.value.as_uint);
297 break;
298 case TRACE_VALUE_TYPE_INT:
299 print_length = sprintfn(&output[0], kTraceArgBufferLength, "%lld",
300 arg.value.as_int);
301 break;
302 case TRACE_VALUE_TYPE_DOUBLE:
303 print_length = sprintfn(&output[0], kTraceArgBufferLength, "%f",
304 arg.value.as_double);
305 break;
306 case TRACE_VALUE_TYPE_POINTER:
307 print_length = sprintfn(&output[0], kTraceArgBufferLength, "\"%p\"",
308 arg.value.as_pointer);
309 break;
310 }
311 size_t output_length = print_length < kTraceArgBufferLength
312 ? print_length
313 : kTraceArgBufferLength - 1;
314 // This will hopefully be very close to nop. On most implementations, it
315 // just writes null byte and sets the length field of the string.
316 output.resize(output_length);
317 }
318
319 return output;
320 }
321
322 rtc::CriticalSection crit_;
323 std::vector<TraceEvent> trace_events_ RTC_GUARDED_BY(crit_);
324 rtc::PlatformThread logging_thread_;
325 rtc::Event shutdown_event_;
326 rtc::ThreadChecker thread_checker_;
327 FILE* output_file_ = nullptr;
328 bool output_file_owned_ = false;
329 };
330
EventTracingThreadFunc(void * params)331 static void EventTracingThreadFunc(void* params) {
332 static_cast<EventLogger*>(params)->Log();
333 }
334
335 static EventLogger* volatile g_event_logger = nullptr;
336 static const char* const kDisabledTracePrefix = TRACE_DISABLED_BY_DEFAULT("");
InternalGetCategoryEnabled(const char * name)337 const unsigned char* InternalGetCategoryEnabled(const char* name) {
338 const char* prefix_ptr = &kDisabledTracePrefix[0];
339 const char* name_ptr = name;
340 // Check whether name contains the default-disabled prefix.
341 while (*prefix_ptr == *name_ptr && *prefix_ptr != '\0') {
342 ++prefix_ptr;
343 ++name_ptr;
344 }
345 return reinterpret_cast<const unsigned char*>(*prefix_ptr == '\0' ? ""
346 : name);
347 }
348
InternalAddTraceEvent(char phase,const unsigned char * category_enabled,const char * name,unsigned long long id,int num_args,const char ** arg_names,const unsigned char * arg_types,const unsigned long long * arg_values,unsigned char flags)349 void InternalAddTraceEvent(char phase,
350 const unsigned char* category_enabled,
351 const char* name,
352 unsigned long long id,
353 int num_args,
354 const char** arg_names,
355 const unsigned char* arg_types,
356 const unsigned long long* arg_values,
357 unsigned char flags) {
358 // Fast path for when event tracing is inactive.
359 if (rtc::AtomicOps::AcquireLoad(&g_event_logging_active) == 0)
360 return;
361
362 g_event_logger->AddTraceEvent(name, category_enabled, phase, num_args,
363 arg_names, arg_types, arg_values,
364 rtc::TimeMicros(), 1, rtc::CurrentThreadId());
365 }
366
367 } // namespace
368
SetupInternalTracer()369 void SetupInternalTracer() {
370 RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr(
371 &g_event_logger, static_cast<EventLogger*>(nullptr),
372 new EventLogger()) == nullptr);
373 webrtc::SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent);
374 }
375
StartInternalCaptureToFile(FILE * file)376 void StartInternalCaptureToFile(FILE* file) {
377 if (g_event_logger) {
378 g_event_logger->Start(file, false);
379 }
380 }
381
StartInternalCapture(const char * filename)382 bool StartInternalCapture(const char* filename) {
383 if (!g_event_logger)
384 return false;
385
386 FILE* file = fopen(filename, "w");
387 if (!file) {
388 RTC_LOG(LS_ERROR) << "Failed to open trace file '" << filename
389 << "' for writing.";
390 return false;
391 }
392 g_event_logger->Start(file, true);
393 return true;
394 }
395
StopInternalCapture()396 void StopInternalCapture() {
397 if (g_event_logger) {
398 g_event_logger->Stop();
399 }
400 }
401
ShutdownInternalTracer()402 void ShutdownInternalTracer() {
403 StopInternalCapture();
404 EventLogger* old_logger = rtc::AtomicOps::AcquireLoadPtr(&g_event_logger);
405 RTC_DCHECK(old_logger);
406 RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr(
407 &g_event_logger, old_logger,
408 static_cast<EventLogger*>(nullptr)) == old_logger);
409 delete old_logger;
410 webrtc::SetupEventTracer(nullptr, nullptr);
411 }
412
413 } // namespace tracing
414 } // namespace rtc
415