Trace_event upgrades

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..d3afd39dbb8183674d20f073ab4f28083cc7ac7a 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,218 @@
 namespace base {
 namespace debug {
 
-static const char* kEventTypeNames[] = {
-  "BEGIN",
-  "END",
-  "INSTANT"
-};
+#define GPU_TRACE_MAX_EVENTS_TO_BUFFER 16384

[rvargas (doing something else), 2011/02/25 23:38:33]

?

+
+////////////////////////////////////////////////////////////////////////////////
+//
+// 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) {
+  if (phase== TRACE_EVENT_PHASE_BEGIN) {
+    return "B";
+  } else if (phase == TRACE_EVENT_PHASE_INSTANT) {
+    return "I";
+  } else if (phase == TRACE_EVENT_PHASE_END) {
+    return "E";
+  } else {
+    DCHECK(false);
+    return "?";
+  }
+}
 }
 
-// static
-bool TraceLog::IsTracing() {
-  return TraceLog::GetInstance()->enabled_;
+void TraceEvent::AppendAsJSON(std::string& out,
+    const std::vector<TraceEvent>& events) {
+  out += "[";
+  for (size_t i = 0; i < events.size(); ++i) {
+    if (i > 0)
+      out += ",";
+    events[i].AppendAsJSON(out);
+  }
+  out += "]";

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

Are there more efficient ways of building up C++ strings than using the +
operator?

 }
 
-// static
-bool TraceLog::StartTracing() {
-  return TraceLog::GetInstance()->Start();
+void TraceEvent::AppendAsJSON(std::string& out) const {
+  int nargs = 0;
+  for (int i = 0; i < TRACE_MAX_NUM_ARGS; ++i) {
+    if (argNames[i] == NULL)
+      break;
+    nargs += 1;
+  }
+
+  const char* phaseStr = GetPhaseStr(phase);
+  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 += "}}";
 }
 
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceLog
+//
+////////////////////////////////////////////////////////////////////////////////
+
 // static
-void TraceLog::StopTracing() {
-  return TraceLog::GetInstance()->Stop();
+TraceLog* TraceLog::GetInstance() {
+  return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
 }
 
-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);
+TraceLog::TraceLog()
+    : enabled_(false)
+{
+  logged_events_.reserve(1024);
 }
 
-void TraceLog::Trace(const std::string& name,
-                     EventType type,
-                     const void* id,
-                     const std::string& extra,
-                     const char* file,
-                     int line) {
-  if (!enabled_)
-    return;
-
-#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
+TraceLog::~TraceLog() {
 }
 
-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
+  for (int i = 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_,
+                                    static_cast<base::subtle::Atomic32>(1));
+    }
+  } else {
+    /* disable all categories */
+    for (size_t i = 0; i < categories_.size(); i++) {
+      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_) {
-    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() {
+  if (output_callback_.get() && logged_events_.size()) {
+    std::string json_events;
+    TraceEvent::AppendAsJSON(json_events, logged_events_);
+    output_callback_->Run(json_events);
   }
+  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,
+    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()),
+  AutoLock lock(lock_);
+  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);
+
+  if (logged_events_.size() > GPU_TRACE_MAX_EVENTS_TO_BUFFER)
+    FlushWithLockAlreadyHeld();
 }
 
-void TraceLog::Log(const std::string& msg) {
-  AutoLock lock(file_lock_);
+void TraceLog::AddTraceEventLegacy(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("Legacy Trace Event");
+  if (category->enabled_) {
+    AddTraceEvent(phase, file, line, category, name,
+                  "id", StringPrintf("%p", id).c_str(),
+                  "extra", extra ? extra : "");
+  }
 }
 
 }  // namespace debug