Implement standalone event tracing in AppRTCDemo.

webrtc/base/event_tracer.cc

Index: webrtc/base/event_tracer.cc
diff --git a/webrtc/base/event_tracer.cc b/webrtc/base/event_tracer.cc
index 5c6d39f0a49219d24cd307d1d2610eb13a54658f..7dcfb51fdc5556de1fceeb70dd810338f6fe9b94 100644
--- a/webrtc/base/event_tracer.cc
+++ b/webrtc/base/event_tracer.cc
@@ -7,15 +7,26 @@
  *  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 = 0;
-AddTraceEventPtr g_add_trace_event_ptr = 0;
+GetCategoryEnabledPtr g_get_category_enabled_ptr = nullptr;
+AddTraceEventPtr g_add_trace_event_ptr = nullptr;
 
 }  // namespace
 
@@ -25,7 +36,6 @@ void SetupEventTracer(GetCategoryEnabledPtr 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);
@@ -34,7 +44,8 @@ const unsigned char* EventTracer::GetCategoryEnabled(const char* name) {
   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,
@@ -57,4 +68,197 @@ void EventTracer::AddTraceEvent(char phase,
   }
 }
 
+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"),
+        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_)
+      return;
+    trace_events_.push_back(
+        TraceEvent{name, category_enabled, phase, timestamp, 1, thread_id});

[tommi, 2015/11/24 16:27:09]

Are we using this syntax anywhere else?

[pbos-webrtc, 2015/11/26 12:21:07]

I found like one instance of it in a test, removed TraceEvent in front of it
since that was superfluous. Are you fine with this?

+  }
+
+  void Log() {

[tommi, 2015/11/24 16:27:09]

can you add a link to some documentation about this format?
If we can have a regression test to make sure we're in sync with Chromium, then
that would be great.

[pbos-webrtc, 2015/11/26 12:21:07]

Added documentation link. The upstream repo even links to this google doc:
https://github.com/catapult-project/catapult/blob/master/tracing/README.md

+    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);
+      std::vector<TraceEvent> events;
+      bool shutting_down;
+      {
+        rtc::CritScope lock(&crit_);
+        trace_events_.swap(events);
+        shutting_down = !enabled_;
+      }
+      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_EQ(0, rtc::AtomicOps::AcquireLoad(&g_event_logging_active))
+        << "Internal tracing should not start twice.";
+    RTC_DCHECK(!output_file_);
+    output_file_ = file;
+    output_file_owned_ = owned;
+    {
+      rtc::CritScope lock(&crit_);
+      enabled_ = true;

[tommi, 2015/11/24 16:27:09]

do we need both enabled_ and g_event_logging_active?

[pbos-webrtc, 2015/11/26 12:21:07]

Yes, because g_event_logging_active is a fast path and best effort. The actual
synchronization of trace_events_ for instance happens based on enabled_ and
crit_ locking.

Checking g_event_logging by AtomicLoad is just a regular read instruction on
x86, so way faster than taking the lock and aborting when we're not logging.

+    }
+    rtc::AtomicOps::ReleaseStore(&g_event_logging_active, 1);

[tommi, 2015/11/24 16:27:09]

can we rather do this in a CompareExhange step and do it at the top?  If the
swap operation fails, [D]CHECK.
As is, the check above is racy.  Multiple threads could successfully pass it.

[pbos-webrtc, 2015/11/26 12:21:07]

Done.

+
+    // Finally start, everything should be set up now.
+    logging_thread_.Start();
+  }
+
+  void Stop() {
+    // Abort if we're not currently logging.
+    {
+      rtc::CritScope lock(&crit_);
+      if (!enabled_)
+        return;
+      enabled_ = false;
+    }
+    // Disable event logging (fast-path).
+    rtc::AtomicOps::ReleaseStore(&g_event_logging_active, 0);

[tommi, 2015/11/24 16:27:09]

CompareExchange instead.

[pbos-webrtc, 2015/11/26 12:21:07]

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;
+  const char* name_ptr = name;
+  // Check whether name contains the default-disabled prefix.
+  while (*prefix_ptr == *name_ptr) {
+    ++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);
+}
+
+}  // namespace
+
+// static
+void EventTracer::SetupInternalTracer() {
+  RTC_DCHECK(!g_get_category_enabled_ptr);
+  RTC_DCHECK(!g_add_trace_event_ptr);
+  RTC_DCHECK(!g_event_logger);
+  g_event_logger = new EventLogger();
+  SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent);
+}
+
+void EventTracer::StartInternalCaptureToFile(FILE* file) {
+  RTC_DCHECK(g_event_logger);
+  g_event_logger->Start(file, false);
+}
+
+bool EventTracer::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 EventTracer::StopInternalCapture() {
+  RTC_DCHECK(g_event_logger);
+  g_event_logger->Stop();
+}
+
+void EventTracer::ShutdownInternalTracer() {
+  StopInternalCapture();
+  RTC_DCHECK(g_get_category_enabled_ptr == InternalGetCategoryEnabled);
+  RTC_DCHECK(g_add_trace_event_ptr == InternalAddTraceEvent);
+  RTC_DCHECK(g_event_logger);
+  SetupEventTracer(nullptr, nullptr);
+  delete g_event_logger;
+  g_event_logger = nullptr;
+}
+
 }  // namespace webrtc