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>
+
+#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/timeutils.h"
+#include "webrtc/base/trace_event.h"
+#include "webrtc/base/platform_thread.h"
+#include "webrtc/system_wrappers/include/thread_wrapper.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
@@ skipping 21 matching lines @@
                           name,
                           id,
                           num_args,
                           arg_names,
                           arg_types,
                           arg_values,
                           flags);
   }
 }
 
+namespace {
+
+struct TraceEvent {
+  const char* name;
+  const unsigned char* category_enabled;

[tommi, 2015/11/20 13:49:54]

uint8_t?

[pbos-webrtc, 2015/11/20 15:11:05]

Consistent with AddTraceEvent functions.

+  char phase;

[tommi, 2015/11/20 13:49:54]

what is phase used for?
Is this code borrowed from Chrome to some extent? Can we link to the code on
which this is based, especially format related code?  Would it make sense to
have a test, maybe compile-time type checks, that guarantee compatibility of
webrtc trace logs with chrome's?

[pbos-webrtc, 2015/11/20 15:11:05]

Done, by referring to webrtc/base/trace_event.h. W/r/t testing, I'd assume
changing those would break existing trace files, but if there should be a test
for this I'd think of it separate (and probably written in Chromium to make sure
that its trace_event.h remains using the same symbols.

Phase is an event type (begin, end, instant) etc.

+  uint64_t timestamp;
+  int pid;
+  rtc::PlatformThreadId tid;
+};
+
+const unsigned char* InternalGetCategoryEnabled(const char* name) {
+  return reinterpret_cast<const unsigned char*>(
+      strstr(name, TRACE_DISABLED_BY_DEFAULT("")) == name ? "" : name);

[tommi, 2015/11/20 13:49:54]

I'm not groking what this actually does or is supposed to do.  if name ==
"webrtc" for example, then this will be:

strstr("webrtc", "disabled-by-default-") == "webrtc" ? "" : "webrtc");

Did you mean to pass 'name' to TRACE_DISABLED_BY_DEFAULT?  That actually doesn't
make sense to me either, so render me confused :)

[pbos-webrtc, 2015/11/20 15:11:05]

Should be a prefix search, I was lazy and did strstr, fixed in another patchset.

+}
+
+static volatile int g_event_logging_active = 0;
+static rtc::CriticalSection* g_event_crit;

[tommi, 2015/11/20 13:49:54]

also initialize?

can we bundle these variables in a single class and have only a single global
pointer?

[pbos-webrtc, 2015/11/20 15:11:05]

class done

+static std::vector<TraceEvent>* g_event_trace_events GUARDED_BY(g_event_crit) =
+    nullptr;
+
+// Logging thread "members".
+static ThreadWrapper* g_event_logging_thread = nullptr;
+static rtc::Event* g_event_wakeup_event = nullptr;
+static FILE* g_event_output_file = nullptr;
+static bool g_event_output_file_owned;

[tommi, 2015/11/20 13:49:54]

and this one?

[pbos-webrtc, 2015/11/20 15:11:05]

Done.

+
+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 tid = rtc::CurrentThreadId();
+  rtc::CritScope lock(g_event_crit);
+  if (g_event_trace_events == nullptr)
+    return;
+  g_event_trace_events->push_back(
+      TraceEvent{name, category_enabled, phase, timestamp, 1, tid});
+}
+
+// TODO(pbos): Log metadata for all threads, etc.
+bool LoggingThread(void* obj) {
+  static const int kLoggingIntervalMs = 100;
+  fprintf(g_event_output_file, "{ \"traceEvents\": [\n");
+  bool has_logged_event = false;
+  while (true) {
+    g_event_wakeup_event->Wait(kLoggingIntervalMs);
+    std::vector<TraceEvent> events;
+    {
+      rtc::CritScope lock(g_event_crit);
+      g_event_trace_events->swap(events);
+    }
+    for (const TraceEvent e : events) {

[tommi, 2015/11/20 13:49:54]

copy by value intentionally or missing &?

[pbos-webrtc, 2015/11/20 15:11:05]

Done.

+      fprintf(g_event_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 (rtc::AtomicOps::AcquireLoad(&g_event_logging_active) == 0)
+      break;
+  }
+  fprintf(g_event_output_file, "]}\n");
+  if (g_event_output_file_owned)
+    fclose(g_event_output_file);
+  {
+    rtc::CritScope lock(g_event_crit);
+    delete g_event_trace_events;
+    g_event_trace_events = nullptr;
+  }
+  // We're done, so return false to prevent another run w/ wait.
+  return false;
+}
+
+void StartInternalCaptureToFilePtr(FILE* output_file,
+                                   bool file_owned_by_tracer) {
+  RTC_DCHECK(!g_event_crit) << "Internal tracing not initialized.";
+  RTC_DCHECK(!g_event_logging_thread)
+      << "Internal tracing should not start twice.";
+  RTC_DCHECK_EQ(0, rtc::AtomicOps::AcquireLoad(&g_event_logging_active));
+  g_event_output_file = output_file;

[tommi, 2015/11/20 13:49:54]

how do we know we're not overwriting a previous value?  I don't see that it's
guaranteed that StartInternalCaptureToFilePtr isn't called on different threads.
 It seems like there should be a CompareAndSwap atomic operation instead of just
Load.

[pbos-webrtc, 2015/11/20 15:11:05]

Assuming that start and stop are done on the same thread Stop triggers removal
of the output file, so it can't start at the same time.

+  g_event_output_file_owned = file_owned_by_tracer;
+  {
+    rtc::CritScope lock(g_event_crit);
+    g_event_trace_events = new std::vector<TraceEvent>();
+  }
+  g_event_wakeup_event = new rtc::Event(false, false);
+  g_event_logging_thread =
+      ThreadWrapper::CreateThread(&LoggingThread, nullptr, "EventTracingThread")

[tommi, 2015/11/20 13:49:54]

instead of having g_event_output_file be a global, can we pass it to the thread
here and let the thread own it?
if we need to pass the owned flag too, consider passing them in a struct that's
owned by the thread.

[pbos-webrtc, 2015/11/20 15:11:05]

-> class

+          .release();
+  rtc::AtomicOps::ReleaseStore(&g_event_logging_active, 1);
+
+  // Finally start, everything should be set up now.
+  g_event_logging_thread->Start();
+}
+
+}  // namespace
+
+// static
+void EventTracer::SetupInternalTracer() {
+  RTC_DCHECK(!g_get_category_enabled_ptr);
+  RTC_DCHECK(!g_add_trace_event_ptr);
+  g_event_crit = new rtc::CriticalSection();
+  SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent);
+}
+
+void EventTracer::StartInternalCaptureToFile(FILE* file) {
+  StartInternalCaptureToFilePtr(file, false);
+}
+
+bool EventTracer::StartInternalCapture(const char* filename) {
+  FILE* file = fopen(filename, "w");
+  if (!file) {
+    LOG(LS_ERROR) << "Failed to open trace file '" << filename
+                  << "' for writing.";
+    return false;
+  }
+  StartInternalCaptureToFilePtr(file, true);
+  return true;
+}
+
+void EventTracer::StopInternalCapture() {
+  // Abort if we're not currently logging.
+  if (rtc::AtomicOps::AcquireLoad(&g_event_logging_active) == 0)

[tommi, 2015/11/20 13:49:54]

this should also be a CompareAndSwap since otherwise we have a race (even though
we're using atomics)

[pbos-webrtc, 2015/11/20 15:11:05]

This is only a best-effort fast path for early abort. I've added an enabled_
that's protected within the logging class to make sure no events are logged
after we've stopped. Checking that one instead now.

+    return;
+  // Disable event logging.
+  rtc::AtomicOps::ReleaseStore(&g_event_logging_active, 0);
+  // Wake up logging thread to finish writing.
+  g_event_wakeup_event->Set();
+  // Join the logging thread.
+  g_event_logging_thread->Stop();
+  delete g_event_logging_thread;
+  delete g_event_wakeup_event;
+  g_event_logging_thread = nullptr;
+  g_event_wakeup_event = nullptr;
+}
+
+void EventTracer::ShutdownInternalTracer() {
+  StopInternalCapture();
+  RTC_DCHECK(g_get_category_enabled_ptr == InternalGetCategoryEnabled);
+  RTC_DCHECK(g_add_trace_event_ptr == InternalAddTraceEvent);
+  SetupEventTracer(nullptr, nullptr);
+  delete g_event_crit;
+  g_event_crit = nullptr;
+}
+
 }  // namespace webrtc