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];

[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) {
+}
+
+TraceCategory::~TraceCategory() {
+  enabled_ = false;
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// 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;
+}
+
+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;
+}
+
+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 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;
+  }
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// 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, 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){
+    static TraceCategory false_category_after_shutdown = TraceCategory();
+    return &false_category_after_shutdown;
+  }
+  return tracelog->GetCategoryInternal(name);
+}
+
+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];
+}
+
+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;
+    }
+  }
+  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::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::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;
-  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_)
+  if (logged_events_.size() >= TRACE_EVENT_BUFFER_SIZE)
     return;
-
-#ifdef USE_UNRELIABLE_NOW
-  TimeTicks tick = TimeTicks::HighResNow();
-#else
-  TimeTicks tick = TimeTicks::Now();
+  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::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
-  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() {
-  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", 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 : "");
+  }
+}
+
+void TraceLog::Resurrect() {
+  StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
 }  // namespace debug
 }  // namespace base