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
24 namespace webrtc {
25
26 namespace {
27
28 GetCategoryEnabledPtr g_get_category_enabled_ptr = nullptr;
29 AddTraceEventPtr g_add_trace_event_ptr = nullptr;
30
31 } // namespace
32
SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr,AddTraceEventPtr add_trace_event_ptr)33 void 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
GetCategoryEnabled(const char * name)39 const 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.
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)49 void 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
73 namespace rtc {
74 namespace tracing {
75 namespace {
76
77 static bool EventTracingThreadFunc(void* params);
78
79 // Atomic-int fast path for avoiding logging when disabled.
80 static volatile int g_event_logging_active = 0;
81
82 // TODO(pbos): Log metadata for all threads, etc.
83 class EventLogger final {
84 public:
EventLogger()85 EventLogger()
86 : logging_thread_(EventTracingThreadFunc, this, "EventTracingThread"),
87 shutdown_event_(false, false) {}
~EventLogger()88 ~EventLogger() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); }
89
AddTraceEvent(const char * name,const unsigned char * category_enabled,char phase,uint64_t timestamp,int pid,rtc::PlatformThreadId thread_id)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
Log()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
Start(FILE * file,bool owned)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
Stop()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
EventTracingThreadFunc(void * params)193 static bool EventTracingThreadFunc(void* params) {
194 static_cast<EventLogger*>(params)->Log();
195 return true;
196 }
197
198 static EventLogger* volatile g_event_logger = nullptr;
199 static const char* const kDisabledTracePrefix = TRACE_DISABLED_BY_DEFAULT("");
InternalGetCategoryEnabled(const char * name)200 const 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
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)212 void 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
SetupInternalTracer()231 void 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
StartInternalCaptureToFile(FILE * file)239 void StartInternalCaptureToFile(FILE* file) {
240 g_event_logger->Start(file, false);
241 }
242
StartInternalCapture(const char * filename)243 bool 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
StopInternalCapture()254 void StopInternalCapture() {
255 g_event_logger->Stop();
256 }
257
ShutdownInternalTracer()258 void 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