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..2973955dd9df8b4451e652cf3fff8909bf9cb9d1 100644
--- a/webrtc/base/event_tracer.cc
+++ b/webrtc/base/event_tracer.cc
@@ -7,15 +7,27 @@
  *  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/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
 
@@ -57,4 +69,164 @@ void EventTracer::AddTraceEvent(char phase,
   }
 }
 
+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