webrtc/base/event_tracer.cc

/*
 *  Copyright (c) 2012 The WebRTC project authors. All Rights Reserved.
 *
 *  Use of this source code is governed by a BSD-style license
 *  that can be found in the LICENSE file in the root of the source
 *  tree. An additional intellectual property rights grant can be found
 *  in the file PATENTS.  All contributing project authors may
 *  be found in the AUTHORS file in the root of the source tree.
 */
#include "webrtc/base/event_tracer.h"

#include <inttypes.h>

#include <vector>

#include "webrtc/base/checks.h"
#include "webrtc/base/criticalsection.h"
#include "webrtc/base/event.h"
#include "webrtc/base/logging.h"
#include "webrtc/base/platform_thread.h"
#include "webrtc/base/timeutils.h"
#include "webrtc/base/trace_event.h"

namespace webrtc {

namespace {

GetCategoryEnabledPtr g_get_category_enabled_ptr = nullptr;
AddTraceEventPtr g_add_trace_event_ptr = nullptr;

}  // namespace

void SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr,
                      AddTraceEventPtr add_trace_event_ptr) {
  g_get_category_enabled_ptr = get_category_enabled_ptr;
  g_add_trace_event_ptr = add_trace_event_ptr;
}

const unsigned char* EventTracer::GetCategoryEnabled(const char* name) {
  if (g_get_category_enabled_ptr)
    return g_get_category_enabled_ptr(name);

  // A string with null terminator means category is disabled.
  return reinterpret_cast<const unsigned char*>("\0");
}

// Arguments to this function (phase, etc.) are as defined in
// webrtc/base/trace_event.h.
void EventTracer::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) {
  if (g_add_trace_event_ptr) {
    g_add_trace_event_ptr(phase,
                          category_enabled,
                          name,
                          id,
                          num_args,
                          arg_names,
                          arg_types,
                          arg_values,
                          flags);
  }
}

}  // namespace webrtc

namespace rtc {
namespace tracing {
namespace {

static bool EventTracingThreadFunc(void* params);

// Atomic-int fast path for avoiding logging when disabled.
static volatile int g_event_logging_active = 0;

// TODO(pbos): Log metadata for all threads, etc.
class EventLogger final {
 public:
  EventLogger()
      : logging_thread_(EventTracingThreadFunc, this, "EventTracingThread"),
        shutdown_event_(false, false) {}
  ~EventLogger() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); }

  void AddTraceEvent(const char* name,
                     const unsigned char* category_enabled,
                     char phase,
                     uint64_t timestamp,
                     int pid,
                     rtc::PlatformThreadId thread_id) {
    rtc::CritScope lock(&crit_);
    trace_events_.push_back(
        {name, category_enabled, phase, timestamp, 1, thread_id});
  }

// The TraceEvent format is documented here:
// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
  void Log() {
    RTC_DCHECK(output_file_);
    static const int kLoggingIntervalMs = 100;
    fprintf(output_file_, "{ \"traceEvents\": [\n");
    bool has_logged_event = false;
    while (true) {
      bool shutting_down = shutdown_event_.Wait(kLoggingIntervalMs);
      std::vector<TraceEvent> events;
      {
        rtc::CritScope lock(&crit_);
        trace_events_.swap(events);
      }
      for (const TraceEvent& e : events) {
        fprintf(output_file_,
                "%s{ \"name\": \"%s\""
                ", \"cat\": \"%s\""
                ", \"ph\": \"%c\""
                ", \"ts\": %" PRIu64
                ", \"pid\": %d"
#if defined(WEBRTC_WIN)
                ", \"tid\": %lu"
#else
                ", \"tid\": %d"
#endif  // defined(WEBRTC_WIN)
                "}\n",
                has_logged_event ? "," : " ", e.name, e.category_enabled,
                e.phase, e.timestamp, e.pid, e.tid);
        has_logged_event = true;
      }
      if (shutting_down)
        break;
    }
    fprintf(output_file_, "]}\n");
    if (output_file_owned_)
      fclose(output_file_);
    output_file_ = nullptr;
  }

  void Start(FILE* file, bool owned) {
    RTC_DCHECK(thread_checker_.CalledOnValidThread());
    RTC_DCHECK(file);
    RTC_DCHECK(!output_file_);
    output_file_ = file;
    output_file_owned_ = owned;
    {
      rtc::CritScope lock(&crit_);
      // Since the atomic fast-path for adding events to the queue can be
      // bypassed while the logging thread is shutting down there may be some
      // stale events in the queue, hence the vector needs to be cleared to not
      // log events from a previous logging session (which may be days old).
      trace_events_.clear();
    }
    // Enable event logging (fast-path). This should be disabled since starting
    // shouldn't be done twice.
    RTC_CHECK_EQ(0,
                 rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 0, 1));

    // Finally start, everything should be set up now.
    logging_thread_.Start();
    TRACE_EVENT_INSTANT0("webrtc", "EventLogger::Start");
    logging_thread_.SetPriority(kLowPriority);
  }

  void Stop() {
    RTC_DCHECK(thread_checker_.CalledOnValidThread());
    TRACE_EVENT_INSTANT0("webrtc", "EventLogger::Stop");
    // Try to stop. Abort if we're not currently logging.
    if (rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 1, 0) == 0)
      return;

    // Wake up logging thread to finish writing.
    shutdown_event_.Set();
    // Join the logging thread.
    logging_thread_.Stop();
  }

 private:
  struct TraceEvent {
    const char* name;
    const unsigned char* category_enabled;
    char phase;
    uint64_t timestamp;
    int pid;
    rtc::PlatformThreadId tid;
  };

  rtc::CriticalSection crit_;
  std::vector<TraceEvent> trace_events_ GUARDED_BY(crit_);
  rtc::PlatformThread logging_thread_;
  rtc::Event shutdown_event_;
  rtc::ThreadChecker thread_checker_;
  FILE* output_file_ = nullptr;
  bool output_file_owned_ = false;
};

static bool EventTracingThreadFunc(void* params) {
  static_cast<EventLogger*>(params)->Log();
  // False indicates that the thread function has done its job and doesn't need
  // to be restarted again. Log() runs its own internal loop.
  return false;
}

static EventLogger* volatile g_event_logger = nullptr;
static const char* const kDisabledTracePrefix = TRACE_DISABLED_BY_DEFAULT("");
const unsigned char* InternalGetCategoryEnabled(const char* name) {
  const char* prefix_ptr = &kDisabledTracePrefix[0];
  const char* name_ptr = name;
  // Check whether name contains the default-disabled prefix.
  while (*prefix_ptr == *name_ptr && *prefix_ptr != '\0') {
    ++prefix_ptr;
    ++name_ptr;
  }
  return reinterpret_cast<const unsigned char*>(*prefix_ptr == '\0' ? ""
                                                                    : name);
}

void 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) {
  // Fast path for when event tracing is inactive.
  if (rtc::AtomicOps::AcquireLoad(&g_event_logging_active) == 0)
    return;

  g_event_logger->AddTraceEvent(name, category_enabled, phase,
                                rtc::TimeMicros(), 1, rtc::CurrentThreadId());
}

}  // namespace

void SetupInternalTracer() {
  RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr(
                &g_event_logger, static_cast<EventLogger*>(nullptr),
                new EventLogger()) == nullptr);
  webrtc::SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent);
}

void StartInternalCaptureToFile(FILE* file) {
  g_event_logger->Start(file, false);
}

bool StartInternalCapture(const char* filename) {
  FILE* file = fopen(filename, "w");
  if (!file) {
    LOG(LS_ERROR) << "Failed to open trace file '" << filename
                  << "' for writing.";
    return false;
  }
  g_event_logger->Start(file, true);
  return true;
}

void StopInternalCapture() {
  g_event_logger->Stop();
}

void ShutdownInternalTracer() {
  StopInternalCapture();
  EventLogger* old_logger = rtc::AtomicOps::AcquireLoadPtr(&g_event_logger);
  RTC_DCHECK(old_logger);
  RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr(
                &g_event_logger, old_logger,
                static_cast<EventLogger*>(nullptr)) == old_logger);
  delete old_logger;
  webrtc::SetupEventTracer(nullptr, nullptr);
}

}  // namespace tracing
}  // namespace rtc