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..156e0708e4e148e13ebf8c488726686e090bcf50 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -1,16 +1,15 @@
-// Copyright (c) 2010 The Chromium Authors. All rights reserved.
+// Copyright (c) 2011 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #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,344 @@
 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
 
-static const FilePath::CharType* kLogFileName =
-    FILE_PATH_LITERAL("trace_%d.log");
+#define TRACE_EVENT_MAX_CATEGORIES 42
 
-// static
-TraceLog* TraceLog::GetInstance() {
-  return Singleton<TraceLog, DefaultSingletonTraits<TraceLog> >::get();
+static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES];

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

This will unfortunately not work, and will not pass review, see
[http://www.chromium.org/developers/coding-style#Static_Variables]. Using static
storage for the class instances is the right thing to do, but as-is you have an
initialization race between the C++ runtime and the user of this array - which
could legitimately be called from a static initializer or during destruction.
I'm afraid you'll have to manage your storage manually, and/or make sure the
TraceCategories are PODs.

[scheib, 2011/05/04 02:14:15]

Converted to POD.

+static int g_category_index = 0;
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceLog::Category
+//
+////////////////////////////////////////////////////////////////////////////////
+TraceCategory::TraceCategory()
+    : enabled_(false), name_(NULL) {
 }
 
-// static
-bool TraceLog::IsTracing() {
-  return TraceLog::GetInstance()->enabled_;
+TraceCategory::~TraceCategory() {
+  enabled_ = false;
 }
 
-// static
-bool TraceLog::StartTracing() {
-  return TraceLog::GetInstance()->Start();
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceValue
+//
+////////////////////////////////////////////////////////////////////////////////
+
+void TraceValue::Destroy() {
+  if (type_ == TRACE_TYPE_STRING) {
+    free(value_.as_string);

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

Per
http://codesearch.google.com/codesearch/p?hl=en#OAMlx_jo-ck/src/base/string_u...:

// Chromium code style is to not use malloc'd strings; this is only for use
// for interaction with APIs that require it.

[scheib, 2011/05/04 02:14:15]

Done.

+    value_.as_string = NULL;
+  }
+  type_ = TRACE_TYPE_UNDEFINED;
+  value_.as_uint = 0ull;
 }
 
-// static
-void TraceLog::StopTracing() {
-  return TraceLog::GetInstance()->Stop();
+TraceValue& TraceValue::operator=(const TraceValue& rhs) {
+  DCHECK(sizeof(value_) == sizeof(uint64));

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

COMPILE_ASSERT?

[scheib, 2011/05/04 02:14:15]

Refactored, assert not needed.

+  Destroy();
+  type_ = rhs.type_;
+  if (rhs.type_ == TRACE_TYPE_STRING) {
+    value_.as_string = base::strdup(rhs.value_.as_string);
+  } else {
+    // Copy all 64 bits for all other types.

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

Move the assert from above here, by way of documentation as to why this works?

[scheib, 2011/05/04 02:14:15]

Refactored, assert not needed.

+    value_.as_uint = rhs.value_.as_uint;
+  }
+  return *this;
 }
 
-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);
+bool TraceValue::operator==(const TraceValue& rhs) const {
+  if (type_ != rhs.type())
+    return false;
+  if (rhs.type_ == TRACE_TYPE_STRING) {
+    return (strcmp(value_.as_string, rhs.value_.as_string) == 0);
+  } else {
+    // Compare all 64 bits for all other types. Unused bits are set to zero
+    // by the constructors of types that may be less than 64 bits.
+    return (value_.as_uint == rhs.value_.as_uint);

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

mmmm, are you sure that doubles have a canonical representation for all possible
values?
Do you need equality comparison to begin with?

[scheib, 2011/05/04 02:14:15]

Refactored, assert not needed.

+  }
 }
 
-void TraceLog::Trace(const std::string& name,
-                     EventType type,
-                     const void* id,
-                     const std::string& extra,
-                     const char* file,
-                     int line) {
-  if (!enabled_)
-    return;
+void TraceValue::AppendAsJSON(std::string* out) const {
+  char temp_string[128];
+  std::string::size_type start_pos;
+  switch (type_) {
+  case TRACE_TYPE_BOOL:
+    *out += as_bool()? "true" : "false";
+    break;
+  case TRACE_TYPE_UINT:
+    base::snprintf(temp_string, sizeof(temp_string), "%llu",

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: sizeof->arraysize

[scheib, 2011/05/04 02:14:15]

Done.

+                   static_cast<unsigned long long>(as_uint()));
+    *out += temp_string;
+    break;
+  case TRACE_TYPE_INT:
+    base::snprintf(temp_string, sizeof(temp_string), "%lld",
+                   static_cast<long long>(as_int()));
+    *out += temp_string;
+    break;
+  case TRACE_TYPE_DOUBLE:
+    base::snprintf(temp_string, sizeof(temp_string), "%f", as_double());
+    *out += temp_string;
+    break;
+  case TRACE_TYPE_POINTER:
+    base::snprintf(temp_string, sizeof(temp_string), "%llu",
+                   static_cast<unsigned long long>(
+                     reinterpret_cast<intptr_t>(
+                       as_pointer())));
+    *out += temp_string;
+    break;
+  case TRACE_TYPE_STRING:
+    *out += "\"";
+    start_pos = out->size();
+    *out += as_string();
+    // replace " character with '
+    while ((start_pos = out->find_first_of('\"', start_pos)) !=
+           std::string::npos)
+      (*out)[start_pos] = '\'';
+    *out += "\"";
+    break;
+  default:
+    break;
+  }
+}
 
-#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
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceEvent
+//
+////////////////////////////////////////////////////////////////////////////////
+
+namespace {
+
+const char* GetPhaseStr(TraceEventPhase phase) {
+  switch(phase) {
+  case TRACE_EVENT_PHASE_BEGIN:

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: see style guide for indentation:
http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml?showone=Loops_...

[scheib, 2011/05/04 02:14:15]

Done.

+    return "B";
+  case TRACE_EVENT_PHASE_INSTANT:
+    return "I";
+  case TRACE_EVENT_PHASE_END:
+    return "E";
+  default:
+    DCHECK(false);

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

NOTREACHED() << "Some comment";?

[scheib, 2011/05/04 02:14:15]

Done.

+    return "?";
+  }
+}
+
+}  // namespace
+
+TraceEvent::TraceEvent()
+    : process_id(0),
+      thread_id(0),
+      phase(TRACE_EVENT_PHASE_BEGIN),
+      category(NULL),
+      name(NULL) {
+  memset(&arg_names, 0, sizeof(arg_names));
+}
+
+TraceEvent::~TraceEvent() {
+}
+

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: spurious line.

[scheib, 2011/05/04 02:14:15]

Done.

+
+void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
+    size_t start,

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: align to bracket.

[scheib, 2011/05/04 02:14:15]

Done.

+    size_t count,
+    std::string* out) {
+  *out += "[";
+  for (size_t i = 0; i < count && start + i < events.size(); ++i) {
+    if (i > 0)
+      *out += ",";
+    events[i + start].AppendAsJSON(out);
+  }
+  *out += "]";
+}
+
+void TraceEvent::AppendAsJSON(std::string* out) const {
+  const char* phase_str = GetPhaseStr(phase);
+  int64 time_int64 = timestamp.ToInternalValue();
+  StringAppendF(out,
+      "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%lld,"

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: the JSON won't be well-formed if any of the strings to %s contain quotes,
is there an assert or a check that prevents this someplace?

[scheib, 2011/05/04 02:14:15]

Done.

+      "\"ph\":\"%s\",\"name\":\"%s\",\"args\":{",
+      category->name(),
+      static_cast<int>(process_id),
+      static_cast<int>(thread_id),
+      static_cast<long long>(time_int64),
+      phase_str,
+      name);
+
+  // Output argument names and values, stop at first NULL argument name.
+  for (int  i = 0; i < TRACE_MAX_NUM_ARGS && arg_names[i]; ++i) {
+    if (i > 0)
+      *out += ",";
+    *out += "\"";
+    *out += arg_names[i];
+    *out += "\":";
+    arg_values[i].AppendAsJSON(out);
+  }
+  *out += "}}";
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceLog
+//
+////////////////////////////////////////////////////////////////////////////////
+
+// static
+TraceLog* TraceLog::GetInstance() {
+  return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
+}
+
+TraceLog::TraceLog()
+    : enabled_(false) {
+  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) {
+  TraceLog* tracelog = GetInstance();
+  if (!tracelog){
+    static TraceCategory false_category_after_shutdown = TraceCategory();
+    return &false_category_after_shutdown;
   }
-  return true;
+  return tracelog->GetCategoryInternal(name);
 }
 
-void TraceLog::CloseLogFile() {
-  if (log_file_) {
-    file_util::CloseFile(log_file_);
+TraceCategory* TraceLog::GetCategoryInternal(const char* name) {
+  AutoLock lock(lock_);
+  for (int i = 0; i < g_category_index; i++) {
+    if (strcmp(g_categories[i].name(), name) == 0)
+      return &g_categories[i];
   }
+  CHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) <<

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

This seems quite severe for release builds.
Assuming that there's a few little used nookies and crannies that refer to
distinct trace categories, you might expect them only to get exercised under
long and varied use, which is only likely to happen in release builds in the
wild... 
(nobody said it would be easy :).

I'd suggest a DCHECK, but logging error and returning a dummy category on
spillover in release builds. What do you think?

[scheib, 2011/05/04 02:14:15]

Done.

Two special case categories added for post shutdown and category overflow.

+      "must increase TRACE_EVENT_MAX_CATEGORIES";
+  int new_index = g_category_index++;
+  g_categories[new_index].set(name, enabled_);
+  return &g_categories[new_index];
 }
 
-bool TraceLog::Start() {
-  if (enabled_)
-    return true;
-  enabled_ = OpenLogFile();
-  if (enabled_) {
-    Log("var raw_trace_events = [\n");
-    trace_start_time_ = TimeTicks::Now();
-    timer_.Start(TimeDelta::FromMilliseconds(250), this, &TraceLog::Heartbeat);
+void TraceLog::SetEnabled(bool enabled) {
+  {
+    AutoLock lock(lock_);
+    if (enabled == enabled_)
+      return;
+    enabled_ = enabled;
+    for (int i = 0; i < g_category_index; i++) {
+      g_categories[i].enabled_ = enabled;
+    }
   }
-  return enabled_;
+  if (!enabled)
+    Flush();
+}
+
+float TraceLog::GetBufferPercentFull() const {
+  return (float)((double)logged_events_.size()/(double)TRACE_EVENT_BUFFER_SIZE);
+}
+
+void TraceLog::SetOutputCallback(TraceLog::OutputCallback* cb) {
+  Flush();
+  AutoLock lock(lock_);
+  output_callback_.reset(cb);
 }
 
-void TraceLog::Stop() {
-  if (enabled_) {
-    enabled_ = false;
-    Log("];\n");
-    CloseLogFile();
-    timer_.Stop();
+void TraceLog::SetBufferFullCallback(TraceLog::BufferFullCallback* cb) {
+  AutoLock lock(lock_);
+  buffer_full_callback_.reset(cb);
+}
+
+void TraceLog::AddRemotelyCollectedData(const std::string& json_events) {
+  AutoLock lock(lock_);
+  if (output_callback_.get())
+    output_callback_->Run(json_events);
+}
+
+void TraceLog::Flush() {
+  std::vector<TraceEvent> previous_logged_events;
+  {
+    AutoLock lock(lock_);
+    previous_logged_events.swap(logged_events_);
+  }
+
+  for (size_t i = 0;
+       i < previous_logged_events.size();
+       i += TRACE_EVENT_BATCH_SIZE) {
+    std::string json_events;
+    TraceEvent::AppendEventsAsJSON(previous_logged_events,
+                                   i,
+                                   TRACE_EVENT_BATCH_SIZE,
+                                   &json_events);
+    {
+      AutoLock lock(lock_);
+      output_callback_->Run(json_events);

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

You're still calling out of module here with the lock held, was that the intent?
This is generally frowned upon with event notification machinery, as it
typically creates deadlock potential.

[scheib, 2011/05/04 02:14:15]

This was an error and I've removed the lock. The callbacks must be (and are, see
trace_controller.cc) thread-safe.

+    }
   }
 }
 
-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* arg1_name, TraceValue arg1_val,
+    const char* arg2_name, TraceValue arg2_val) {
+  DCHECK(file && name);
+#ifdef USE_UNRELIABLE_NOW
+  TimeTicks now = TimeTicks::HighResNow();
+#else
+  TimeTicks now = TimeTicks::Now();
+#endif
+  AutoLock lock(lock_);
+  if (!enabled_ || !category->enabled_)
+    return;
+  if (logged_events_.size() >= TRACE_EVENT_BUFFER_SIZE)
+    return;
+  logged_events_.push_back(TraceEvent());
+  TraceEvent& event = logged_events_.back();
+  event.process_id = static_cast<unsigned long>(base::GetCurrentProcId());
+  event.thread_id = PlatformThread::CurrentId();
+  event.timestamp = now;
+  event.phase = phase;
+  event.category = category;
+  event.name = name;
+  event.arg_names[0] = arg1_name;
+  event.arg_values[0] = arg1_val;
+  event.arg_names[1] = arg2_name;
+  event.arg_values[1] = arg2_val;
+  COMPILE_ASSERT(TRACE_MAX_NUM_ARGS == 2, TraceEvent_arc_count_out_of_sync);
+  if (logged_events_.size() == TRACE_EVENT_BUFFER_SIZE &&
+      buffer_full_callback_.get())
+    buffer_full_callback_->Run();

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

you're calling out of module here under a lock also?

[scheib, 2011/05/04 02:14:15]

Fixed.

 }
 
-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
+
+  // Also add new trace event behavior
+  static TraceCategory* category = GetCategory("ETW Trace Event");
+  if (category->enabled_) {
+    TraceLog* tracelog = TraceLog::GetInstance();
+    if (!tracelog)
+      return;
+    tracelog->AddTraceEvent(phase, file, line, category, name,
+                  "id", StringPrintf("%p", id).c_str(),

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: wonky indent.

[scheib, 2011/05/04 02:14:15]

Done.

+                  "extra", extra ? extra : "");
+  }
+}
 
-  fprintf(log_file_, "%s", msg.c_str());
+void TraceLog::Resurrect() {
+  StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
 }  // namespace debug