Merge gpu_trace_event back into base/debug/trace_event

base/debug/trace_event.cc

Index: base/debug/trace_event.cc
diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index c219cec293b1dd35c999fae2fa0df90af0480f08..3f6b50a7988c749f10e8cd3dc2db212626f0481a 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -4,13 +4,12 @@
 
 #include "base/debug/trace_event.h"
 
+#if defined(OS_WIN)
+#include "base/debug/trace_event_win.h"
+#endif
 #include "base/format_macros.h"
-#include "base/file_path.h"
-#include "base/file_util.h"
-#include "base/path_service.h"
 #include "base/process_util.h"
 #include "base/stringprintf.h"
-#include "base/threading/platform_thread.h"
 #include "base/utf_string_conversions.h"
 #include "base/time.h"
 
@@ -19,149 +18,237 @@
 namespace base {
 namespace debug {
 
-static const char* kEventTypeNames[] = {
-  "BEGIN",
-  "END",
-  "INSTANT"
-};
+// Controls the number of trace events we will buffer in-memory
+// before throwing them away.
+#define TRACE_EVENT_BUFFER_SIZE 500000
+#define TRACE_EVENT_BATCH_SIZE 1000
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceLog::Category
+//
+////////////////////////////////////////////////////////////////////////////////
+TraceCategory::TraceCategory(const char* name, bool enabled)
+    : name_(name) {
+  base::subtle::NoBarrier_Store(&enabled_,
+      static_cast<base::subtle::Atomic32>(enabled));
+}
 
-static const FilePath::CharType* kLogFileName =
-    FILE_PATH_LITERAL("trace_%d.log");
+TraceCategory::~TraceCategory() {
+  base::subtle::NoBarrier_Store(&enabled_,
+      static_cast<base::subtle::Atomic32>(0));
+}
 
-// static
-TraceLog* TraceLog::GetInstance() {
-  return Singleton<TraceLog, DefaultSingletonTraits<TraceLog> >::get();
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceEvent
+//
+////////////////////////////////////////////////////////////////////////////////
+
+namespace {
+const char* GetPhaseStr(TraceEventPhase phase) {

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: one blank line after opening namespace.

[scheib, 2011/04/27 21:20:10]

Done.

+  if (phase== TRACE_EVENT_PHASE_BEGIN) {

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: phase == 

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

perhaps this is better phrased as a switch?

[scheib, 2011/04/27 21:20:10]

Done.

[scheib, 2011/04/27 21:20:10]

Done.

[scheib, 2011/04/27 21:20:10]

Done.

+    return "B";
+  } else if (phase == TRACE_EVENT_PHASE_INSTANT) {
+    return "I";
+  } else if (phase == TRACE_EVENT_PHASE_END) {
+    return "E";
+  } else {
+    DCHECK(false);
+    return "?";
+  }
+}
 }

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: one blank line before closing namespace
}  // namespace

[scheib, 2011/04/27 21:20:10]

Done.

 
-// static
-bool TraceLog::IsTracing() {
-  return TraceLog::GetInstance()->enabled_;
+TraceEvent::TraceEvent()
+    : processId(0),
+      threadId(0),
+      phase(TRACE_EVENT_PHASE_BEGIN),
+      category(NULL),
+      name(NULL) {
+  memset(&argNames, 0, sizeof(argNames));
 }
 
-// static
-bool TraceLog::StartTracing() {
-  return TraceLog::GetInstance()->Start();
+TraceEvent::~TraceEvent() {
 }
 
-// static
-void TraceLog::StopTracing() {
-  return TraceLog::GetInstance()->Stop();
+void TraceEvent::AppendAsJSON(std::string* out,

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

First input args, then output args:

http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml?showone=Functi...

[scheib, 2011/04/27 21:20:10]

Done.

+    const std::vector<TraceEvent>& events,
+    size_t start,
+    size_t count) {
+  *out += "[";
+  for (size_t i = 0; i < count && start + i < events.size(); ++i) {
+    if (i > 0)
+      *out += ",";
+    events[i + start].AppendAsJSON(out);
+  }
+  *out += "]";
 }
 
-void TraceLog::Trace(const std::string& name,
-                     EventType type,
-                     const void* id,
-                     const std::wstring& extra,
-                     const char* file,
-                     int line) {
-  if (!enabled_)
-    return;
-  Trace(name, type, id, WideToUTF8(extra), file, line);
+void TraceEvent::AppendAsJSON(std::string* out) const {
+  int nargs = 0;

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

some running commentary would make this function easier to read.

[scheib, 2011/04/27 21:20:10]

Done.

+  for (int i = 0; i < TRACE_MAX_NUM_ARGS; ++i) {
+    if (argNames[i] == NULL)
+      break;
+    nargs += 1;
+  }
+
+  const char* phaseStr = GetPhaseStr(phase);

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

phaseStr->phase_str

[scheib, 2011/04/27 21:20:10]

Done.

+  int64 time_int64 = timestamp.ToInternalValue();
+  long long unsigned int time_llui =
+      static_cast<long long unsigned int>(time_int64);
+  StringAppendF(out,
+      "{cat:'%s',pid:%i,tid:%i,ts:0x%llx,ph:'%s',name:'%s',args:{",
+      category->name(),
+      static_cast<int>(processId),
+      static_cast<int>(threadId),
+      time_llui,
+      phaseStr,
+      name);
+  for (int  i = 0; i < nargs; ++i) {
+    if (i > 0)
+      *out += ",";
+    *out += argNames[i];
+    *out += ":'";
+    *out += argValues[i];
+    *out += "'";
+  }
+  *out += "}}";
 }
 
-void TraceLog::Trace(const std::string& name,
-                     EventType type,
-                     const void* id,
-                     const std::string& extra,
-                     const char* file,
-                     int line) {
-  if (!enabled_)
-    return;
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceLog
+//
+////////////////////////////////////////////////////////////////////////////////
 
-#ifdef USE_UNRELIABLE_NOW
-  TimeTicks tick = TimeTicks::HighResNow();
-#else
-  TimeTicks tick = TimeTicks::Now();
-#endif
-  TimeDelta delta = tick - trace_start_time_;
-  int64 usec = delta.InMicroseconds();
-  std::string msg =
-    StringPrintf("{'pid':'0x%lx', 'tid':'0x%lx', 'type':'%s', "
-                 "'name':'%s', 'id':'%p', 'extra':'%s', 'file':'%s', "
-                 "'line_number':'%d', 'usec_begin': %" PRId64 "},\n",
-                 static_cast<unsigned long>(base::GetCurrentProcId()),
-                 static_cast<unsigned long>(PlatformThread::CurrentId()),
-                 kEventTypeNames[type],
-                 name.c_str(),
-                 id,
-                 extra.c_str(),
-                 file,
-                 line,
-                 usec);
-
-  Log(msg);
-}
-
-TraceLog::TraceLog() : enabled_(false), log_file_(NULL) {
-  base::ProcessHandle proc = base::GetCurrentProcessHandle();
-#if !defined(OS_MACOSX)
-  process_metrics_.reset(base::ProcessMetrics::CreateProcessMetrics(proc));
-#else
-  // The default port provider is sufficient to get data for the current
-  // process.
-  process_metrics_.reset(base::ProcessMetrics::CreateProcessMetrics(proc,
-                                                                    NULL));
-#endif
+// static
+TraceLog* TraceLog::GetInstance() {
+  return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
+}
+
+TraceLog::TraceLog()
+    : enabled_(false)
+{

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: bracket placement.

[scheib, 2011/04/27 21:20:10]

Done.

+  logged_events_.reserve(1024);
 }
 
 TraceLog::~TraceLog() {
-  Stop();
-}
-
-bool TraceLog::OpenLogFile() {
-  FilePath::StringType pid_filename =
-      StringPrintf(kLogFileName, base::GetCurrentProcId());
-  FilePath log_file_path;
-  if (!PathService::Get(base::DIR_EXE, &log_file_path))
-    return false;
-  log_file_path = log_file_path.Append(pid_filename);
-  log_file_ = file_util::OpenFile(log_file_path, "a");
-  if (!log_file_) {
-    // try the current directory
-    log_file_ = file_util::OpenFile(FilePath(pid_filename), "a");
-    if (!log_file_) {
-      return false;
-    }
+}
+
+TraceCategory* TraceLog::GetCategory(const char* name) {
+  AutoLock lock(lock_);
+  // TODO(nduca): replace with a hash_map.

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

Yes, suggest adding an efficient name lookup before checkin.

[scheib, 2011/04/27 21:20:10]

Categories moved to static array. Categories are cached at trace call sites, so
look up performance doesn't seem important to optimize here.

+  for (int i = static_cast<int>(categories_.size()) - 1; i >= 0; i-- ) {
+    if (strcmp(categories_[i]->name(), name) == 0)
+      return categories_[i];
   }
-  return true;
+  TraceCategory* category = new TraceCategory(name, enabled_);
+  categories_.push_back(category);
+  return category;
 }
 
-void TraceLog::CloseLogFile() {
-  if (log_file_) {
-    file_util::CloseFile(log_file_);
+void TraceLog::SetEnabled(bool enabled) {
+  AutoLock lock(lock_);
+  if (enabled == enabled_)
+    return;
+  if (enabled) {
+    // Enable all categories
+    enabled_ = true;
+    for (size_t i = 0; i < categories_.size(); i++) {
+      base::subtle::NoBarrier_Store(&categories_[i]->enabled_,

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

better to encapsulate the flag in inline accessors to reduce clutter.

[scheib, 2011/04/27 21:20:10]

Removed, changed to just a bool.

+                                    static_cast<base::subtle::Atomic32>(1));
+    }
+  } else {
+    // Disable all categories.
+    for (size_t i = 0; i < categories_.size(); i++) {

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

copy paste loop, better to copy the test and do pre/post work conditionally.

[scheib, 2011/04/27 21:20:10]

Done.

+      base::subtle::NoBarrier_Store(&categories_[i]->enabled_,
+                                    static_cast<base::subtle::Atomic32>(0));
+    }
+    enabled_ = false;
+    FlushWithLockAlreadyHeld();
   }
 }
 
-bool TraceLog::Start() {
-  if (enabled_)
-    return true;
-  enabled_ = OpenLogFile();
+void TraceLog::SetOutputCallback(TraceLog::OutputCallback* cb) {
+  AutoLock lock(lock_);
   if (enabled_) {

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: no brackets for an uncomplicated one-line compound statement.

[scheib, 2011/04/27 21:20:10]

Done.

-    Log("var raw_trace_events = [\n");
-    trace_start_time_ = TimeTicks::Now();
-    timer_.Start(TimeDelta::FromMilliseconds(250), this, &TraceLog::Heartbeat);
+    FlushWithLockAlreadyHeld();
   }
-  return enabled_;
+  output_callback_.reset(cb);
 }
 
-void TraceLog::Stop() {
-  if (enabled_) {
-    enabled_ = false;
-    Log("];\n");
-    CloseLogFile();
-    timer_.Stop();
+void TraceLog::AddRemotelyCollectedData(const std::string& json_events) {
+  AutoLock lock(lock_);
+  if (output_callback_.get())
+    output_callback_->Run(json_events);
+}
+
+void TraceLog::Flush() {
+  AutoLock lock(lock_);
+  FlushWithLockAlreadyHeld();
+}
+
+void TraceLog::FlushWithLockAlreadyHeld() {

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

lock_.AssertAcquired()?

[scheib, 2011/04/27 21:20:10]

Done.

+  if (output_callback_.get() && logged_events_.size()) {
+    for (size_t i = 0; i < logged_events_.size(); i += TRACE_EVENT_BATCH_SIZE) {
+      std::string json_events;
+      TraceEvent::AppendAsJSON(&json_events, logged_events_,
+                               i, TRACE_EVENT_BATCH_SIZE);
+      output_callback_->Run(json_events);

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

I really don't like this - e.g. calling out of module with a lock held, on the
usual principles. I would suggest refactoring such that you only do acquire the
events and teh callback under the lock, with e.g. logged_events_.swap(), then
proceed with stringification and everything else outside the lock.
If you feel that ordering is important to the user, I'd suggest adding a
monotonically increasing flush count that you also acquire under the lock, and
pass on to the callback.

[scheib, 2011/04/27 21:20:10]

Done.

+    }
   }
+  logged_events_.erase(logged_events_.begin(), logged_events_.end());
 }
 
-void TraceLog::Heartbeat() {
-  std::string cpu = StringPrintf("%.0f", process_metrics_->GetCPUUsage());
-  TRACE_EVENT_INSTANT("heartbeat.cpu", 0, cpu);
+void TraceLog::AddTraceEvent(TraceEventPhase phase,
+    const char* file, int line,
+    TraceCategory* category,
+    const char* name,
+    const char* arg1name, const char* arg1val,

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

arg1_name, arg1_val, etc

[scheib, 2011/04/27 21:20:10]

Done.

+    const char* arg2name, const char* arg2val) {
+  DCHECK(file && name);
+#ifdef USE_UNRELIABLE_NOW
+  TimeTicks now = TimeTicks::HighResNow();
+#else
+  TimeTicks now = TimeTicks::Now();
+#endif
+  //static_cast<unsigned long>(base::GetCurrentProcId()),

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

?

[scheib, 2011/04/27 21:20:10]

Done.

+  AutoLock lock(lock_);
+  if (logged_events_.size() >= TRACE_EVENT_BUFFER_SIZE)
+    return;
+  logged_events_.push_back(TraceEvent());
+  TraceEvent& event = logged_events_.back();
+  event.processId = static_cast<unsigned long>(base::GetCurrentProcId());
+  event.threadId = PlatformThread::CurrentId();
+  event.timestamp = now;
+  event.phase = phase;
+  event.category = category;
+  event.name = name;
+  event.argNames[0] = arg1name;
+  event.argValues[0] = arg1name ? arg1val : "";
+  event.argNames[1] = arg2name;
+  event.argValues[1] = arg2name ? arg2val : "";
+  COMPILE_ASSERT(TRACE_MAX_NUM_ARGS == 2, TraceEvent_arc_count_out_of_sync);
 }
 
-void TraceLog::Log(const std::string& msg) {
-  AutoLock lock(file_lock_);
+void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
+    const char* file, int line,
+    const char* name,
+    const void* id,
+    const char* extra) {
+  // Legacy trace points on windows called to ETW
+#if defined(OS_WIN)
+  TraceEventETWProvider::Trace(name, phase, id, extra);
+#endif
 
-  fprintf(log_file_, "%s", msg.c_str());
+  // Also add new trace event behavior
+  static TraceCategory* category = GetCategory("ETW Trace Event");
+  if (category->enabled_) {
+    AddTraceEvent(phase, file, line, category, name,
+                  "id", StringPrintf("%p", id).c_str(),
+                  "extra", extra ? extra : "");
+  }
 }
 
 }  // namespace debug