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