Implement standalone event tracing in AppRTCDemo.
Logs tracing events (TRACE_EVENT0 and friends) to storage in a format
compatible with chrome://tracing which can be used for performance
evaluation, finding lock contention and other sweet things). Tracing is
still basic and doesn't contain thread metadata or logging of tracing
arguments.
BUG=webrtc:5158
R=tommi@webrtc.org
Review URL: https://codereview.webrtc.org/1457383002 .
Cr-Commit-Position: refs/heads/master@{#10921}
diff --git a/webrtc/base/atomicops.h b/webrtc/base/atomicops.h
index b21bd99..42b8709 100644
--- a/webrtc/base/atomicops.h
+++ b/webrtc/base/atomicops.h
@@ -43,6 +43,16 @@
new_value,
old_value);
}
+ // Pointer variants.
+ template <typename T>
+ static T* AtomicLoadPtr(T* volatile* ptr) {
+ return *ptr;
+ }
+ template <typename T>
+ static T* CompareAndSwapPtr(T* volatile* ptr, T* old_value, T* new_value) {
+ return static_cast<T*>(::InterlockedCompareExchangePointer(
+ reinterpret_cast<PVOID volatile*>(ptr), old_value, new_value));
+ }
#else
static int Increment(volatile int* i) {
return __sync_add_and_fetch(i, 1);
@@ -59,6 +69,15 @@
static int CompareAndSwap(volatile int* i, int old_value, int new_value) {
return __sync_val_compare_and_swap(i, old_value, new_value);
}
+ // Pointer variants.
+ template <typename T>
+ static T* AtomicLoadPtr(T* volatile* ptr) {
+ return __atomic_load_n(ptr, __ATOMIC_ACQUIRE);
+ }
+ template <typename T>
+ static T* CompareAndSwapPtr(T* volatile* ptr, T* old_value, T* new_value) {
+ return __sync_val_compare_and_swap(ptr, old_value, new_value);
+ }
#endif
};
diff --git a/webrtc/base/event_tracer.cc b/webrtc/base/event_tracer.cc
index 5c6d39f..dbf85a4 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 @@
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 @@
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,
@@ -58,3 +69,197 @@
}
} // 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"
+ ", \"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_);
+ // 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();
+ }
+
+ void 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();
+ return true;
+}
+
+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);
+ g_event_logger = new EventLogger();
+ 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::AtomicLoadPtr(&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
diff --git a/webrtc/base/event_tracer.h b/webrtc/base/event_tracer.h
index cfc6e9e..51c8cfd 100644
--- a/webrtc/base/event_tracer.h
+++ b/webrtc/base/event_tracer.h
@@ -26,6 +26,8 @@
#ifndef WEBRTC_BASE_EVENT_TRACER_H_
#define WEBRTC_BASE_EVENT_TRACER_H_
+#include <stdio.h>
+
namespace webrtc {
typedef const unsigned char* (*GetCategoryEnabledPtr)(const char* name);
@@ -68,4 +70,16 @@
} // namespace webrtc
+namespace rtc {
+namespace tracing {
+// Set up internal event tracer.
+void SetupInternalTracer();
+bool StartInternalCapture(const char* filename);
+void StartInternalCaptureToFile(FILE* file);
+void StopInternalCapture();
+// Make sure we run this, this will tear down the internal tracing.
+void ShutdownInternalTracer();
+} // namespace tracing
+} // namespace rtc
+
#endif // WEBRTC_BASE_EVENT_TRACER_H_