Implement standalone event tracing in AppRTCDemo.

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 "webrtc/base/event_tracer.h"
+#include <inttypes.h>

[tommi, 2015/11/27 22:07:26]

Hm.. have you tried this on the win bots?

[pbos-webrtc, 2015/12/03 15:23:04]

Yep!

+
+#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 = 0;
-AddTraceEventPtr g_add_trace_event_ptr = 0;
+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;
 }
 
-// static
 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");
 }
 
-// static
+// 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.

[tommi, 2015/11/27 22:07:26]

nit: add empty line above this one.

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+class EventLogger final {
+ public:
+  EventLogger()
+      : logging_thread_(EventTracingThreadFunc, this, "EventTracingThread"),
+        wakeup_event_(false, false) {}
+
+  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_);
+    if (!enabled_)

[tommi, 2015/11/27 22:07:26]

Is this check necessary?  We've just checked that the global flag is set, right?

[pbos-webrtc, 2015/12/03 15:23:04]

Done, adding stale events is OK, we clear them on Start now either way.

+      return;
+    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) {
+      wakeup_event_.Wait(kLoggingIntervalMs);

[tommi, 2015/11/27 22:07:26]

let's check for the return value here.  If the event is signaled, we know we're
shutting down.

[pbos-webrtc, 2015/12/03 15:23:04]

Done + renamed.

+      std::vector<TraceEvent> events;
+      bool shutting_down;
+      {
+        rtc::CritScope lock(&crit_);
+        trace_events_.swap(events);
+        shutting_down = !enabled_;

[tommi, 2015/11/27 22:07:26]

and then this check isn't necessary

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+      }
+      for (const TraceEvent& e : events) {
+        fprintf(output_file_,
+                "%s{ \"name\": \"%s\""
+                ", \"cat\": \"%s\""
+                ", \"ph\": \"%c\""
+                ", \"ts\": %" PRIu64
+                ", \"pid\": %d"
+                ", \"tid\": %d}\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(file);
+    RTC_DCHECK(!output_file_);
+    output_file_ = file;
+    output_file_owned_ = owned;
+    {
+      rtc::CritScope lock(&crit_);
+      RTC_DCHECK(!enabled_);
+      enabled_ = true;

[tommi, 2015/11/27 22:07:26]

I don't think we need this variable or this scope

[pbos-webrtc, 2015/12/03 15:23:04]

Done for the variable, scope needed because we need to reset the vector to
remove old events.

After Start() returns logging should be active, so we need to block until events
can be added.

+    }
+    // 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();
+  }
+
+  void Stop() {
+    // Abort if we're not currently logging.
+    {
+      rtc::CritScope lock(&crit_);

[tommi, 2015/11/27 22:07:26]

can lose this scope

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+      if (!enabled_)
+        return;
+      enabled_ = false;
+    }
+    // Disable event logging (fast-path). This should be enabled or we should've
+    // aborted. Start/Stop should not be called concurrently.
+    RTC_CHECK_EQ(1,
+                 rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 1, 0));

[tommi, 2015/11/27 22:07:26]

if we want to allow calling Stop() when not running, we could check the return
value here and bail if we're not running.

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+    // Wake up logging thread to finish writing.
+    wakeup_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_;
+  bool enabled_ GUARDED_BY(crit_) = false;
+  std::vector<TraceEvent> trace_events_ GUARDED_BY(crit_);
+  webrtc::PlatformThread logging_thread_;
+  rtc::Event wakeup_event_;
+  FILE* output_file_ = nullptr;
+  bool output_file_owned_ = false;
+};
+
+static bool EventTracingThreadFunc(void* params) {
+  static_cast<EventLogger*>(params)->Log();
+  return true;
+}
+
+static EventLogger* 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;

[tommi, 2015/11/27 22:07:26]

nit: &kDisabledTracePrefix[0]

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+  const char* name_ptr = name;
+  // Check whether name contains the default-disabled prefix.
+  while (*prefix_ptr == *name_ptr) {

[tommi, 2015/11/27 22:07:26]

what if both strings are "foo"?  Won't we read past the '\0'?

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+    ++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;
+
+  uint64_t timestamp = rtc::TimeMicros();
+  rtc::PlatformThreadId thread_id = rtc::CurrentThreadId();
+  g_event_logger->AddTraceEvent(name, category_enabled, phase, timestamp, 1,
+                                thread_id);

[tommi, 2015/11/27 22:07:26]

nit: can just pass rtc::CurrentThreadId().  (and rtc_TimeMicros() too for that
matter)

[pbos-webrtc, 2015/12/03 15:23:04]

Genious! Done. Derp.

+}
+
+}  // namespace
+
+void SetupInternalTracer() {
+  RTC_DCHECK(!webrtc::g_get_category_enabled_ptr);
+  RTC_DCHECK(!webrtc::g_add_trace_event_ptr);
+  RTC_DCHECK(!g_event_logger);
+  g_event_logger = new EventLogger();

[tommi, 2015/11/27 22:07:26]

since there's no synchronization here, we should at least set this pointer
atomically.  As is, two threads could successfully get here without triggering
the checks.

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+  webrtc::SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent);
+}
+
+void StartInternalCaptureToFile(FILE* file) {
+  RTC_DCHECK(g_event_logger);

[tommi, 2015/11/27 22:07:26]

not necessary since you dereference anyway

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+  g_event_logger->Start(file, false);
+}
+
+bool StartInternalCapture(const char* filename) {
+  RTC_DCHECK(g_event_logger);
+  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() {
+  RTC_DCHECK(g_event_logger);

[tommi, 2015/11/27 22:07:26]

same here

[pbos-webrtc, 2015/12/03 15:23:04]

Done.

+  g_event_logger->Stop();
+}
+
+void ShutdownInternalTracer() {
+  StopInternalCapture();
+  RTC_DCHECK(webrtc::g_get_category_enabled_ptr == InternalGetCategoryEnabled);
+  RTC_DCHECK(webrtc::g_add_trace_event_ptr == InternalAddTraceEvent);
+  RTC_DCHECK(g_event_logger);
+  webrtc::SetupEventTracer(nullptr, nullptr);
+  delete g_event_logger;
+  g_event_logger = nullptr;

[tommi, 2015/11/27 22:07:26]

we need to free this object atomically

[pbos-webrtc, 2015/12/03 15:23:04]

Assuming you mean the CAS we talked about, done.

+}
+
+}  // namespace tracing
+}  // namespace rtc