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
+#define TRACE_EVENT_BATCH_SIZE 1000
+
+#define TRACE_EVENT_MAX_CATEGORIES 42
+
+static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES];
+static TraceCategory* g_category_already_shutdown = NULL;
+static TraceCategory* g_category_categories_exhasted = NULL;
+static const char* g_category_already_shutdown_str =
+  "tracing already shutdown";
+static const char* g_category_categories_exhasted_str =
+  "tracing categories exhasted; must increase TRACE_EVENT_MAX_CATEGORIES";
+static int g_category_index = 0;
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceValue
+//
+////////////////////////////////////////////////////////////////////////////////
+
+void TraceValue::Destroy() {
+  if (type_ == TRACE_TYPE_STRING) {
+    value_.as_string_refptr->Release();
+    value_.as_string_refptr = NULL;

[jbates, 2011/05/03 23:49:10]

it's harmless, but setting to NULL is redundant with line 49.

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

readability is easier with it.. ;)

+  }
+  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:
+      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));
+}
+
+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, '"'));
+  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;
-  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;
-
+  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_);
+  // Initialize special case categories on first run
+  if (g_category_index == 0) {
+    DCHECK(TRACE_EVENT_MAX_CATEGORIES >= 2);
+    g_category_index += 2;
+    g_category_already_shutdown = &g_categories[0];
+    g_category_categories_exhasted = &g_categories[1];
+    DCHECK(!g_category_already_shutdown->enabled);
+    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;

[jbates, 2011/05/03 23:49:10]

Could just put the literal strings here instead of defining globals.

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

Would prefer them next to definition of the pointers, to explain what they are
there

+  }
+
+  // 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;

[jbates, 2011/05/03 23:49:10]

This will silently fail on Release builds, which is I guess is usually what
people will be building when doing trace/perf tests.

That's why I used a CHECK instead of DCHECK.

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

Yes, but as siggi pointed out, we don't want to crash users who are running
chrome for a long time and happen to hit a combination of code paths that
exhaust categories. In development those are less likely to be hit.

Instead, we should fix the viewer of trace data to look for the existence of
this category and warn that categories were maxed out.

+  }
+}
+
+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(TraceLog::OutputCallback* cb) {
+  Flush();
+  AutoLock lock(lock_);
+  output_callback_.reset(cb);
+}
+
+void TraceLog::SetBufferFullCallback(TraceLog::BufferFullCallback* cb) {
+  AutoLock lock(lock_);
+  buffer_full_callback_.reset(cb);
+}
+
+void TraceLog::Flush() {
+  std::vector<TraceEvent> previous_logged_events;
+  {
+    AutoLock lock(lock_);
+    previous_logged_events.swap(logged_events_);
+  } // release lock
+
+  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);
+    output_callback_->Run(json_events);

[jbates, 2011/05/03 23:49:10]

There was a reason for the lock being held during the callback - it's possible
for the callback to be reset on another thread, so this can call a dangling
pointer.

The typical solution for this is recursive mutex, but we don't allow those, so
it seems that the only solution is to document that the callback must not
reenter. Any other ideas?

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

Fixed by moving to new callback form. Thx for help. ;)

+  }
+}
+
+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 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));
+  bool buffer_full = false;
+  {
+    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);
+    buffer_full = logged_events_.size() == TRACE_EVENT_BUFFER_SIZE;
+  } // release lock
+
+  if (buffer_full && buffer_full_callback_.get())
+    buffer_full_callback_->Run();

[jbates, 2011/05/03 23:49:10]

(same problem here with the dangling pointer)

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

Done.

+}
+
+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
-}
-
-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