Home | History | Annotate | Download | only in base 
      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 
     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 
     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.
     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:
     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 
    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("");
    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 
    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 
    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 
    239 void StartInternalCaptureToFile(FILE* file) {
    240   g_event_logger->Start(file, false);
    241 }
    242 
    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 
    254 void StopInternalCapture() {
    255   g_event_logger->Stop();
    256 }
    257 
    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