Introduce gpu_trace_event for gpu performance analysis.

This changelist is a lightweight version of issue 6551019, but with
the code change confined to the gpu subsystem.

The intent of this change is to enable forward progress on gpu tracing.

Work on the aformentioned issue, i.e. fusing gpu_trace_event and trace_event, will continue.

BUG=
TEST=

Review URL: http://codereview.chromium.org/6691013

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@78300 0039d316-1c4b-4281-b951-d872f2087c98

4 files changed, 525 insertions, 0 deletions

diff --git a/gpu/command_buffer/service/gpu_processor.cc b/gpu/command_buffer/service/gpu_processor.cc
index 45d21d7..c7d19d3 100644
--- a/gpu/command_buffer/service/gpu_processor.cc
+++ b/gpu/command_buffer/service/gpu_processor.cc
@@ -9,6 +9,7 @@
 #include "base/compiler_specific.h"
 #include "base/message_loop.h"
 #include "app/gfx/gl/gl_context.h"
+#include "gpu/common/gpu_trace_event.h"
 
 using ::base::SharedMemory;
 
@@ -124,6 +125,7 @@ const unsigned int kMaxOutstandingSwapBuffersCallsPerOnscreenContext = 1;
 #endif
 
 void GPUProcessor::ProcessCommands() {
+  GPU_TRACE_EVENT0("gpu", "GPUProcessor:ProcessCommands");
   CommandBuffer::State state = command_buffer_->GetState();
   if (state.error != error::kNoError)
     return;
diff --git a/gpu/common/gpu_trace_event.cc b/gpu/common/gpu_trace_event.cc
new file mode 100644
index 0000000..d9caec3
--- /dev/null
+++ b/gpu/common/gpu_trace_event.cc
@@ -0,0 +1,216 @@
+// Copyright (c) 2010 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 "gpu/common/gpu_trace_event.h"
+
+#include "base/format_macros.h"
+#include "base/process_util.h"
+#include "base/stringprintf.h"
+#include "base/utf_string_conversions.h"
+#include "base/time.h"
+
+#define USE_UNRELIABLE_NOW
+
+using namespace base;
+
+namespace gpu {
+
+// Controls the number of trace events we will buffer in-memory
+// before flushing them.
+#define TRACE_EVENT_BUFFER_SIZE 16384
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceLog::Category
+//
+////////////////////////////////////////////////////////////////////////////////
+TraceCategory::TraceCategory(const char* name, bool enabled)
+    : name_(name) {
+  base::subtle::NoBarrier_Store(&enabled_,
+      static_cast<base::subtle::Atomic32>(enabled));
+}
+
+TraceCategory::~TraceCategory() {
+  base::subtle::NoBarrier_Store(&enabled_,
+      static_cast<base::subtle::Atomic32>(0));
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
+// TraceEvent
+//
+////////////////////////////////////////////////////////////////////////////////
+
+namespace {
+const char* GetPhaseStr(TraceEventPhase phase) {
+  if (phase == GPU_TRACE_EVENT_PHASE_BEGIN) {
+    return "B";
+  } else if (phase == GPU_TRACE_EVENT_PHASE_INSTANT) {
+    return "I";
+  } else if (phase == GPU_TRACE_EVENT_PHASE_END) {
+    return "E";
+  } else {
+    DCHECK(false);
+    return "?";
+  }
+}
+}
+
+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 += "]";
+}
+
+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
+TraceLog* TraceLog::GetInstance() {
+  return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
+}
+
+TraceLog::TraceLog()
+    : enabled_(false)
+{
+  logged_events_.reserve(1024);
+}
+
+TraceLog::~TraceLog() {
+}
+
+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];
+  }
+  TraceCategory* category = new TraceCategory(name, enabled_);
+  categories_.push_back(category);
+  return category;
+}
+
+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();
+  }
+}
+
+void TraceLog::SetOutputCallback(TraceLog::OutputCallback* cb) {
+  AutoLock lock(lock_);
+  if (enabled_) {
+    FlushWithLockAlreadyHeld();
+  }
+  output_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() {
+  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::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() > TRACE_EVENT_BUFFER_SIZE)
+    FlushWithLockAlreadyHeld();
+}
+
+}  // namespace gpu
diff --git a/gpu/common/gpu_trace_event.h b/gpu/common/gpu_trace_event.h
new file mode 100644
index 0000000..1c8e46a
--- /dev/null
+++ b/gpu/common/gpu_trace_event.h
@@ -0,0 +1,291 @@
+// Copyright (c) 2010 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.
+
+// Trace events are for tracking application performance.
+//
+// Events are issued against categories. Whereas LOG's
+// categories are statically defined, TRACE categories are created
+// implicitly with a string. For example:
+//   GPU_TRACE_EVENT_INSTANT0("MY_SUBSYSTEM", "SomeImportantEvent")
+//
+// Events can be INSTANT, or can be pairs of BEGIN and END:
+//   GPU_TRACE_EVENT_BEGIN0("MY_SUBSYSTEM", "SomethingCostly")
+//   doSomethingCostly()
+//   GPU_TRACE_EVENT_END0("MY_SUBSYSTEM", "SomethingCostly")
+//
+// A common use case is to trace entire function scopes. This
+// issues a trace BEGIN and END automatically:
+//   void doSomethingCostly() {
+//     GPU_TRACE_EVENT0("MY_SUBSYSTEM", "doSomethingCostly");
+//     ...
+//   }
+//
+// Additional parameters can be associated with an event:
+//   void doSomethingCostly2(int howMuch) {
+//     GPU_TRACE_EVENT1("MY_SUBSYSTEM", "doSomethingCostly",
+//         "howMuch", StringPrintf("%i", howMuch).c_str());
+//     ...
+//   }
+//
+// The trace system will automatically add to this information the
+// current process id, thread id, a timestamp down to the
+// microsecond, as well as the file and line number of the calling location.
+//
+// By default, trace collection is compiled in, but turned off at runtime.
+// Collecting trace data is the responsibility of the embedding
+// application. In Chrome's case, navigating to about:gpu will turn on
+// tracing and display data collected across all active processes.
+//
+
+#ifndef GPU_TRACE_EVENT_H_
+#define GPU_TRACE_EVENT_H_
+#pragma once
+
+#include "build/build_config.h"
+
+#include <string>
+
+#include "base/scoped_ptr.h"
+#include "base/scoped_vector.h"
+#include "base/atomicops.h"
+#include "base/singleton.h"
+#include "base/time.h"
+#include "base/timer.h"
+#include "base/callback.h"
+#include <vector>
+
+
+// Implementation detail: trace event macros create temporary variables
+// to keep instrumentation overhead low. These macros give each temporary
+// variable a unique name based on the line number to prevent name collissions.
+#define GPU_TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) a##b
+#define GPU_TRACE_EVENT_UNIQUE_IDENTIFIER2(a,b) \
+  GPU_TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b)
+#define GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(name_prefix) \
+  GPU_TRACE_EVENT_UNIQUE_IDENTIFIER2(name_prefix, __LINE__)
+
+// Records a pair of begin and end events called "name" for the current
+// scope, with 0, 1 or 2 associated arguments. If the category is not
+// enabled, then this does nothing.
+#define GPU_TRACE_EVENT0(category, name) \
+  GPU_TRACE_EVENT1(category, name, NULL, NULL)
+#define GPU_TRACE_EVENT1(category, name, arg1name, arg1val) \
+  GPU_TRACE_EVENT2(category, name, arg1name, arg1val, NULL, NULL)
+#define GPU_TRACE_EVENT2(category, name, arg1name, arg1val, arg2name, arg2val) \
+  static gpu::TraceCategory* \
+      GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      gpu::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load(\
+      &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \
+    gpu::TraceLog::GetInstance()->AddTraceEvent( \
+        gpu::GPU_TRACE_EVENT_PHASE_BEGIN, \
+        __FILE__, __LINE__, \
+        GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  } \
+  gpu::internal::TraceEndOnScopeClose __profileScope ## __LINE ( \
+      __FILE__, __LINE__, \
+      GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), name);
+
+// Records a single event called "name" immediately, with 0, 1 or 2
+// associated arguments. If the category is not enabled, then this
+// does nothing.
+#define GPU_TRACE_EVENT_INSTANT0(category, name) \
+  GPU_TRACE_EVENT_INSTANT1(category, name, NULL, NULL)
+#define GPU_TRACE_EVENT_INSTANT1(category, name, arg1name, arg1val) \
+  GPU_TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, NULL, NULL)
+#define GPU_TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static gpu::TraceCategory* \
+      GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      gpu::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load( \
+      &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \
+    gpu::TraceLog::GetInstance()->AddTraceEvent( \
+        gpu::GPU_TRACE_EVENT_PHASE_INSTANT, \
+        __FILE__, __LINE__, \
+        GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  }
+
+// Records a single BEGIN event called "name" immediately, with 0, 1 or 2
+// associated arguments. If the category is not enabled, then this
+// does nothing.
+#define GPU_TRACE_EVENT_BEGIN0(category, name) \
+  GPU_TRACE_EVENT_BEGIN1(category, name, NULL, NULL)
+#define GPU_TRACE_EVENT_BEGIN1(category, name, arg1name, arg1val) \
+  GPU_TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, NULL, NULL)
+#define GPU_TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static gpu::TraceCategory* \
+      GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      gpu::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load( \
+      &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \
+    gpu::TraceLog::GetInstance()->AddTraceEvent( \
+        gpu::GPU_TRACE_EVENT_PHASE_BEGIN, \
+        __FILE__, __LINE__, \
+        GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  }
+
+// Records a single END event for "name" immediately. If the category
+// is not enabled, then this does nothing.
+#define GPU_TRACE_EVENT_END0(category, name) \
+  static gpu::TraceCategory* \
+      GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      gpu::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load( \
+      &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) {  \
+    gpu::TraceLog::GetInstance()->AddTraceEvent( \
+        gpu::GPU_TRACE_EVENT_PHASE_END, \
+        __FILE__, __LINE__, \
+        GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  }
+
+
+namespace gpu {
+
+// Categories allow enabling/disabling of streams of trace events
+// Don't manipulate the category object directly, as this may lead
+// to threading issues. Use the TraceLog methods instead.
+class TraceCategory {
+ public:
+  TraceCategory(const char* name, bool enabled);
+  ~TraceCategory();
+
+  const char* name() const { return name_; }
+
+  // NEVER read these directly, let the macros do it for you
+  volatile base::subtle::Atomic32 enabled_;
+ protected:
+  const char* name_;
+};
+
+#define TRACE_MAX_NUM_ARGS 2
+
+enum TraceEventPhase {
+  GPU_TRACE_EVENT_PHASE_BEGIN,
+  GPU_TRACE_EVENT_PHASE_END,
+  GPU_TRACE_EVENT_PHASE_INSTANT
+};
+
+// Output records are "Events" and can be obtained via the
+// OutputCallback whenever the logging system decides to flush. This
+// can happen at any time, on any thread, or you can programatically
+// force it to happen.
+struct TraceEvent {
+  static void AppendAsJSON(std::string* out,
+      const std::vector<TraceEvent>& events);
+  void AppendAsJSON(std::string* out) const;
+
+
+  unsigned long processId;
+  unsigned long threadId;
+  base::TimeTicks timestamp;
+  TraceEventPhase phase;
+  TraceCategory* category;
+  const char* name;
+  const char* argNames[TRACE_MAX_NUM_ARGS];
+  std::string argValues[TRACE_MAX_NUM_ARGS];
+};
+
+
+class TraceLog {
+ public:
+  static TraceLog* GetInstance();
+
+  // Global enable of tracing. Currently enables all categories or not.
+  // TODO(nduca) Replaced with an Enable/DisableCategory() that
+  // implicitly controls the global logging state.
+  void SetEnabled(bool enabled);
+
+  // When enough events are collected, they are handed (in bulk) to
+  // the output callback. If no callback is set, the output will be
+  // silently dropped.
+  typedef Callback1<const std::string& /* json_events */>::Type OutputCallback;
+  void SetOutputCallback(OutputCallback* cb);
+
+  // Forwards data collected by a child process to the registered
+  //  output callback.
+  void AddRemotelyCollectedData(const std::string& json_events);
+
+  // Flushes all logged data to the callback.
+  void Flush();
+
+  // Called by GPU_TRACE_EVENT* macros, don't call this directly.
+  TraceCategory* GetCategory(const char* name);
+
+  // Called by GPU_TRACE_EVENT* macros, don't call this directly.
+  void 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);
+
+ private:
+  // This allows constructor and destructor to be private and usable only
+  // by the Singleton class.
+  friend struct StaticMemorySingletonTraits<TraceLog>;
+
+  TraceLog();
+  ~TraceLog();
+  void FlushWithLockAlreadyHeld();
+
+  // TODO(nduca): switch to per-thread trace buffers to reduce thread
+  // synchronization.
+  base::Lock lock_;
+  bool enabled_;
+  ScopedVector<TraceCategory> categories_;
+  scoped_ptr<OutputCallback> output_callback_;
+  std::vector<TraceEvent> logged_events_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceLog);
+};
+
+namespace internal {
+
+// Used by GPU_TRACE_EVENTx macro. Do not use directly.
+class TraceEndOnScopeClose {
+ public:
+  TraceEndOnScopeClose(const char* file, int line,
+                       TraceCategory* category,
+                       const char* name)
+      : file_(file)
+      , line_(line)
+      , category_(category)
+      , name_(name) { }
+
+  ~TraceEndOnScopeClose() {
+    if (base::subtle::Acquire_Load(&category_->enabled_))
+      gpu::TraceLog::GetInstance()->AddTraceEvent(
+          gpu::GPU_TRACE_EVENT_PHASE_END,
+          file_, line_,
+          category_,
+          name_,
+          NULL, NULL, NULL, NULL);
+  }
+
+ private:
+  const char* file_;
+  int line_;
+  TraceCategory* category_;
+  const char* name_;
+};
+
+}  // namespace internal
+
+}  // namespace gpu
+
+#endif  // GPU_TRACE_EVENT_H_
diff --git a/gpu/gpu.gyp b/gpu/gpu.gyp
index 0fb7581..d53badd 100644
--- a/gpu/gpu.gyp
+++ b/gpu/gpu.gyp
@@ -25,6 +25,20 @@
   },
   'targets': [
     {
+      'target_name': 'gpu_common',
+      'type': 'static_library',
+      'dependencies': [
+        '../base/base.gyp:base',
+      ],
+      'include_dirs': [
+        '..',
+      ],
+      'sources': [
+        'common/gpu_trace_event.cc',
+        'common/gpu_trace_event.h',
+      ],
+    },
+    {
       'target_name': 'command_buffer_common',
       'type': 'static_library',
       'include_dirs': [
@@ -163,6 +177,7 @@
       },
       'dependencies': [
         'command_buffer_common',
+        'gpu_common',
         '../app/app.gyp:app_base',
         '../base/base.gyp:base',
         '../ui/gfx/gfx.gyp:gfx',
@@ -231,6 +246,7 @@
         'command_buffer_client',
         'command_buffer_common',
         'command_buffer_service',
+        'gpu_common',
         'gpu_unittest_utils',
         'gles2_implementation_client_side_arrays',
         'gles2_cmd_helper',