Merge gpu_trace_event back into base/debug/trace_event

base/debug/trace_event.cc

-// 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"
 
 #define USE_UNRELIABLE_NOW
 
 namespace base {
 namespace debug {
 
-static const char* kEventTypeNames[] = {
-  "BEGIN",
-  "END",
-  "INSTANT"
-};
-
-static const FilePath::CharType* kLogFileName =
-    FILE_PATH_LITERAL("trace_%d.log");
+// Controls the number of trace events we will buffer in-memory
+// before throwing them away.
+#define TRACE_EVENT_BUFFER_SIZE 500000

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

const size_t, and ditto for below.

[scheib, 2011/05/05 00:06:37]

Done.

+#define TRACE_EVENT_BATCH_SIZE 1000
+
+#define TRACE_EVENT_MAX_CATEGORIES 42
+
+static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES];

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

nit: you can compile-initialize this to the strings with 
x[] = {
  { "name", false },
  { "name", false },
};

[scheib, 2011/05/05 00:06:37]

Done.

+static TraceCategory* g_category_already_shutdown = NULL;

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

you can compile-time initialize this to 
&g_categories[0] 
and
&g_categories[1]

[scheib, 2011/05/05 00:06:37]

Done.

+static TraceCategory* g_category_categories_exhasted = NULL;

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

exhasted->exhausted

[scheib, 2011/05/05 00:06:37]

Done.

+static const char* g_category_already_shutdown_str =
+  "tracing already shutdown";

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

nit: indent 4 on continuation.

[scheib, 2011/05/05 00:06:37]

Done.

+static const char* g_category_categories_exhasted_str =
+  "tracing categories exhasted; must increase TRACE_EVENT_MAX_CATEGORIES";
+static int g_category_index = 0;

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

and this to 2.

[scheib, 2011/05/05 00:06:37]

Done.

+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceValue
+//
+////////////////////////////////////////////////////////////////////////////////
+
+void TraceValue::Destroy() {
+  if (type_ == TRACE_TYPE_STRING) {
+    value_.as_string_refptr->Release();
+    value_.as_string_refptr = NULL;
+  }
+  type_ = TRACE_TYPE_UNDEFINED;
+  value_.as_uint = 0ull;
+}
+
+TraceValue& TraceValue::operator=(const TraceValue& rhs) {
+  if (this == &rhs)
+    return *this;
+
+  Destroy();
+
+  type_ = rhs.type_;
+  switch(type_) {
+    case TRACE_TYPE_UNDEFINED:
+      return *this;
+    case TRACE_TYPE_BOOL:
+      value_.as_bool = rhs.value_.as_bool;
+      return *this;
+    case TRACE_TYPE_UINT:
+      value_.as_uint = rhs.value_.as_uint;
+      return *this;
+    case TRACE_TYPE_INT:
+      value_.as_int = rhs.value_.as_int;
+      return *this;
+    case TRACE_TYPE_DOUBLE:
+      value_.as_double = rhs.value_.as_double;
+      return *this;
+    case TRACE_TYPE_POINTER:
+      value_.as_pointer = rhs.value_.as_pointer;
+      return *this;
+    case TRACE_TYPE_STRING:
+      value_.as_string_refptr = rhs.value_.as_string_refptr;
+      value_.as_string_refptr->AddRef();
+      return *this;
+    default:
+      NOTREACHED();
+      return *this;
+  }
+}
+
+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, arraysize(temp_string), "%llu",
+                     static_cast<unsigned long long>(as_uint()));
+      *out += temp_string;
+      break;
+    case TRACE_TYPE_INT:
+      base::snprintf(temp_string, arraysize(temp_string), "%lld",
+                     static_cast<long long>(as_int()));
+      *out += temp_string;
+      break;
+    case TRACE_TYPE_DOUBLE:
+      base::snprintf(temp_string, arraysize(temp_string), "%f", as_double());
+      *out += temp_string;
+      break;
+    case TRACE_TYPE_POINTER:
+      base::snprintf(temp_string, arraysize(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:

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

NOTREACHED()?

[scheib, 2011/05/05 00:06:37]

Done.

+      break;
+  }
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceEvent
+//
+////////////////////////////////////////////////////////////////////////////////
+
+namespace {
+
+const char* GetPhaseStr(TraceEventPhase phase) {
+  switch(phase) {
+    case TRACE_EVENT_PHASE_BEGIN:
+      return "B";
+    case TRACE_EVENT_PHASE_INSTANT:
+      return "I";
+    case TRACE_EVENT_PHASE_END:
+      return "E";
+    default:
+      NOTREACHED() << "Invalid phase argument";
+      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));

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

because arrays degenerate to pointers, this caused me momentary pause. While
it's the same thing, I'd suggest:

memset(arg_names, 0, sizeof(arg_names)

[scheib, 2011/05/05 00:06:37]

Done.

+}
+
+TraceEvent::~TraceEvent() {
+}
+
+void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
+                                    size_t start,
+                                    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();
+  DCHECK(!strchr(category->name, '"'));

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

nice, but this only fires (and pretty late) if tracing is enabled

[scheib, 2011/05/05 00:06:37]

Done.

+  DCHECK(!strchr(name, '"'));
+  StringAppendF(out,
+      "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%lld,"
+      "\"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, DefaultSingletonTraits<TraceLog> >::get();
-}
-
-// static
-bool TraceLog::IsTracing() {
-  return TraceLog::GetInstance()->enabled_;
-}
-
-// static
-bool TraceLog::StartTracing() {
-  return TraceLog::GetInstance()->Start();
-}
-
-// static
-void TraceLog::StopTracing() {
-  return TraceLog::GetInstance()->Stop();
-}
-
-void TraceLog::Trace(const std::string& name,
-                     EventType type,
-                     const void* id,
-                     const std::wstring& extra,
-                     const char* file,
-                     int line) {
-  if (!enabled_)
+  return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
+}
+
+TraceLog::TraceLog()
+    : enabled_(false) {
+  logged_events_.reserve(1024);
+}
+
+TraceLog::~TraceLog() {
+}
+
+TraceCategory* TraceLog::GetCategory(const char* name) {
+  TraceLog* tracelog = GetInstance();
+  if (!tracelog){
+    CHECK(g_category_already_shutdown);
+    return g_category_already_shutdown;
+  }
+  return tracelog->GetCategoryInternal(name);
+}
+
+TraceCategory* TraceLog::GetCategoryInternal(const char* name) {
+  AutoLock lock(lock_);

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

this looks like the perfect bottleneck to assert that name does not contain a
quote?

[scheib, 2011/05/05 00:06:37]

Done.

+  // Initialize special case categories on first run
+  if (g_category_index == 0) {
+    DCHECK(TRACE_EVENT_MAX_CATEGORIES >= 2);

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

COMPILE_ASSERT

[scheib, 2011/05/05 00:06:37]

Done.

+    g_category_index += 2;
+    g_category_already_shutdown = &g_categories[0];
+    g_category_categories_exhasted = &g_categories[1];
+    DCHECK(!g_category_already_shutdown->enabled);

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

you can also COMPILE_ASSERT this

[scheib, 2011/05/05 00:06:37]

Done.

+    DCHECK(!g_category_categories_exhasted->enabled);
+    g_category_already_shutdown->name = g_category_already_shutdown_str;
+    g_category_categories_exhasted->name = g_category_categories_exhasted_str;
+  }
+
+  // Search for pre-existing category matching this name
+  for (int i = 0; i < g_category_index; i++) {
+    if (strcmp(g_categories[i].name, name) == 0)
+      return &g_categories[i];
+  }
+
+  // Create a new category
+  DCHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) <<
+      "must increase TRACE_EVENT_MAX_CATEGORIES";
+  if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) {
+    int new_index = g_category_index++;
+    g_categories[new_index].name = name;
+    DCHECK(!g_categories[new_index].enabled);
+    g_categories[new_index].enabled = enabled_;
+    return &g_categories[new_index];
+  } else {
+    return g_category_categories_exhasted;
+  }
+}
+
+void TraceLog::SetEnabled(bool enabled) {
+  {
+    AutoLock lock(lock_);
+    if (enabled == enabled_)
+      return;
+    enabled_ = enabled;
+    for (int i = 0; i < g_category_index; i++) {
+      //TODO(scheib): If changed to enable specific categories instead of all
+      // check GetCategoryInternal creation code that users TraceLog::enabled_
+      g_categories[i].enabled = enabled;
+    }
+  } // release lock
+  if (!enabled)
+    Flush();
+}
+
+float TraceLog::GetBufferPercentFull() const {
+  return (float)((double)logged_events_.size()/(double)TRACE_EVENT_BUFFER_SIZE);
+}
+
+void TraceLog::SetOutputCallback(const TraceLog::OutputCallback& cb) {
+  Flush();
+  AutoLock lock(lock_);
+  output_callback_ = cb;
+}
+
+void TraceLog::SetBufferFullCallback(const TraceLog::BufferFullCallback& cb) {
+  AutoLock lock(lock_);
+  buffer_full_callback_ = cb;
+}
+
+void TraceLog::Flush() {
+  std::vector<TraceEvent> previous_logged_events;
+  OutputCallback output_callback_copy;
+  {
+    AutoLock lock(lock_);
+    previous_logged_events.swap(logged_events_);
+    output_callback_copy = output_callback_;
+  } // release lock
+
+  if (output_callback_copy.is_null())
     return;
-  Trace(name, type, id, WideToUTF8(extra), file, line);
-}
-
-void TraceLog::Trace(const std::string& name,
-                     EventType type,
-                     const void* id,
-                     const std::string& extra,
-                     const char* file,
-                     int line) {
-  if (!enabled_)
-    return;
-
+
+  for (size_t i = 0;
+       i < previous_logged_events.size();
+       i += TRACE_EVENT_BATCH_SIZE) {
+    scoped_refptr<RefCountedString> json_events_str_ptr =

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

why does the string need to be refcounted?

[scheib, 2011/05/05 00:06:37]

We do not want to copy the string through the additional callbacks downstream.
Strings will be passed to the IO thread for sending via IPC, so the lifetime
exceeds this callback.

+      new RefCountedString();
+    TraceEvent::AppendEventsAsJSON(previous_logged_events,
+                                   i,
+                                   TRACE_EVENT_BATCH_SIZE,
+                                   &(json_events_str_ptr->data));
+    output_callback_copy.Run(json_events_str_ptr.get());
+  }
+}
+
+void TraceLog::AddTraceEvent(TraceEventPhase phase,
+    const char* file, int line,

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

nit: indent.

[scheib, 2011/05/05 00:06:37]

Done.

+    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 tick = TimeTicks::HighResNow();
+  TimeTicks now = TimeTicks::HighResNow();
 #else
-  TimeTicks tick = TimeTicks::Now();
+  TimeTicks now = 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));
+  BufferFullCallback buffer_full_callback_copy;
+  {
+    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_arg_count_out_of_sync);
+
+    if (logged_events_.size() == TRACE_EVENT_BUFFER_SIZE) {
+      buffer_full_callback_copy = buffer_full_callback_;
+    }
+  } // release lock
+
+  if (!buffer_full_callback_copy.is_null())
+    buffer_full_callback_copy.Run();
+}
+
+void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
+    const char* file, int line,

[Sigurður Ásgeirsson, 2011/05/04 18:58:08]

nit: indent.

[scheib, 2011/05/05 00:06:37]

Done.

+    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
-}
-
-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;
-    }
-  }
-  return true;
-}
-
-void TraceLog::CloseLogFile() {
-  if (log_file_) {
-    file_util::CloseFile(log_file_);
-  }
-}
-
-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);
-  }
-  return enabled_;
-}
-
-void TraceLog::Stop() {
-  if (enabled_) {
-    enabled_ = false;
-    Log("];\n");
-    CloseLogFile();
-    timer_.Stop();
-  }
-}
-
-void TraceLog::Heartbeat() {
-  std::string cpu = StringPrintf("%.0f", process_metrics_->GetCPUUsage());
-  TRACE_EVENT_INSTANT("heartbeat.cpu", 0, cpu);
-}
-
-void TraceLog::Log(const std::string& msg) {
-  AutoLock lock(file_lock_);
-
-  fprintf(log_file_, "%s", msg.c_str());
+
+  // 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", id,
+                            "extra", extra ? extra : "");
+  }
+}
+
+void TraceLog::Resurrect() {
+  StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
 }  // namespace debug
 }  // namespace base