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