Merge gpu_trace_event back into base/debug/trace_event

base/debug/trace_event.h

 // 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.
 
-// Trace events to track application performance.  Events consist of a name
-// a type (BEGIN, END or INSTANT), a tracking id and extra string data.
-// In addition, the current process id, thread id, a timestamp down to the
-// microsecond and a file and line number of the calling location.
+// Trace events are for tracking application performance.
 //
-// The current implementation logs these events into a log file of the form
-// trace_<pid>.log where it's designed to be post-processed to generate a
-// trace report.  In the future, it may use another mechansim to facilitate
-// real-time analysis.
+// Events are issued against categories. Whereas LOG's
+// categories are statically defined, TRACE categories are created
+// implicitly with a string. For example:
+//   TRACE_EVENT_INSTANT0("MY_SUBSYSTEM", "SomeImportantEvent")
+//
+// Events can be INSTANT, or can be pairs of BEGIN and END:
+//   TRACE_EVENT_BEGIN0("MY_SUBSYSTEM", "SomethingCostly")
+//   doSomethingCostly()
+//   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() {
+//     TRACE_EVENT0("MY_SUBSYSTEM", "doSomethingCostly");
+//     ...
+//   }
+//
+// Additional parameters can be associated with an event:
+//   void doSomethingCostly2(int howMuch) {
+//     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.
+//
+// On Windows, the TRACE_EVENT output to ETW.

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

nit: abortive comment?

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

Done.

 
 #ifndef BASE_DEBUG_TRACE_EVENT_H_
 #define BASE_DEBUG_TRACE_EVENT_H_
 #pragma once
 
 #include "build/build_config.h"
 
-#if defined(OS_WIN)
-// On Windows we always pull in an alternative implementation
-// which logs to Event Tracing for Windows.
-//
-// Note that the Windows implementation is always enabled, irrespective the
-// value of the CHROMIUM_ENABLE_TRACE_EVENT define. The Windows implementation
-// is controlled by Event Tracing for Windows, which will turn tracing on only
-// if there is someone listening for the events it generates.
-#include "base/debug/trace_event_win.h"
-#else  // defined(OS_WIN)
-
 #include <string>
 
 #include "base/memory/scoped_ptr.h"
+#include "base/atomicops.h"
+#include "base/callback.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/memory/scoped_vector.h"
 #include "base/memory/singleton.h"
-#include "base/synchronization/lock.h"
 #include "base/time.h"
 #include "base/timer.h"
-
-#ifndef CHROMIUM_ENABLE_TRACE_EVENT
-#define TRACE_EVENT_BEGIN(name, id, extra) ((void) 0)
-#define TRACE_EVENT_END(name, id, extra) ((void) 0)
-#define TRACE_EVENT_INSTANT(name, id, extra) ((void) 0)
-
-#else  // CHROMIUM_ENABLE_TRACE_EVENT
-// Use the following macros rather than using the TraceLog class directly as the
-// underlying implementation may change in the future.  Here's a sample usage:
-// TRACE_EVENT_BEGIN("v8.run", documentId, scriptLocation);
-// RunScript(script);
-// TRACE_EVENT_END("v8.run", documentId, scriptLocation);
-
-// Record that an event (of name, id) has begun.  All BEGIN events should have
-// corresponding END events with a matching (name, id).
-#define TRACE_EVENT_BEGIN(name, id, extra) \
-  base::debug::TraceLog::GetInstance()->Trace( \
-      name, \
-      base::debug::TraceLog::EVENT_BEGIN, \
-      reinterpret_cast<const void*>(id), \
-      extra, \
-      __FILE__, \
-      __LINE__)
-
-// Record that an event (of name, id) has ended.  All END events should have
-// corresponding BEGIN events with a matching (name, id).
-#define TRACE_EVENT_END(name, id, extra) \
-  base::debug::TraceLog::GetInstance()->Trace( \
-      name, \
-      base::debug::TraceLog::EVENT_END, \
-      reinterpret_cast<const void*>(id), \
-      extra, \
-      __FILE__, \
-      __LINE__)
-
-// Record that an event (of name, id) with no duration has happened.
-#define TRACE_EVENT_INSTANT(name, id, extra) \
-  base::debug::TraceLog::GetInstance()->Trace( \
-      name, \
-      base::debug::TraceLog::EVENT_INSTANT, \
-      reinterpret_cast<const void*>(id), \
-      extra, \
-      __FILE__, \
-      __LINE__)
-#endif  // CHROMIUM_ENABLE_TRACE_EVENT
+#include "base/callback.h"
+#include "base/string_util.h"
+#include <vector>
+
+// Older style trace macros with explicit id and extra data
+// Only these macros result in publishing data to ETW as currently implemented.
+#define TRACE_EVENT_BEGIN_ETW(name, id, extra) \
+  base::debug::TraceLog::AddTraceEventEtw( \
+      base::debug::TRACE_EVENT_PHASE_BEGIN, \
+      __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+
+#define TRACE_EVENT_END_ETW(name, id, extra) \
+  base::debug::TraceLog::AddTraceEventEtw( \
+      base::debug::TRACE_EVENT_PHASE_END, \
+      __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+
+#define TRACE_EVENT_INSTANT_ETW(name, id, extra) \
+  base::debug::TraceLog::AddTraceEventEtw( \
+      base::debug::TRACE_EVENT_PHASE_INSTANT, \
+      __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+
+
+// 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 TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) a##b
+#define TRACE_EVENT_UNIQUE_IDENTIFIER2(a,b) \
+  TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b)
+#define TRACE_EVENT_UNIQUE_IDENTIFIER(name_prefix) \
+  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 TRACE_EVENT0(category, name) \
+  TRACE_EVENT1(category, name, NULL, 0)
+#define TRACE_EVENT1(category, name, arg1name, arg1val) \
+  TRACE_EVENT2(category, name, arg1name, arg1val, NULL, 0)
+#define TRACE_EVENT2(category, name, arg1name, arg1val, arg2name, arg2val) \

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

the name arguments here are expected to have infinite lifetime? This warrants a
comment? 

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

Done.

+  static base::debug::TraceCategory* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetCategory(category); \
+  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled_) { \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+        base::debug::TRACE_EVENT_PHASE_BEGIN, \
+        __FILE__, __LINE__, \
+        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  } \
+  base::debug::internal::TraceEndOnScopeClose \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(profileScope) ( \
+          __FILE__, __LINE__, \
+          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 TRACE_EVENT_INSTANT0(category, name) \
+  TRACE_EVENT_INSTANT1(category, name, NULL, 0)
+#define TRACE_EVENT_INSTANT1(category, name, arg1name, arg1val) \
+  TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, NULL, 0)
+#define TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static base::debug::TraceCategory* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetCategory(category); \
+  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled_) { \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+        base::debug::TRACE_EVENT_PHASE_INSTANT, \
+        __FILE__, __LINE__, \
+        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 TRACE_EVENT_BEGIN0(category, name) \
+  TRACE_EVENT_BEGIN1(category, name, NULL, 0)
+#define TRACE_EVENT_BEGIN1(category, name, arg1name, arg1val) \
+  TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, NULL, 0)
+#define TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static base::debug::TraceCategory* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetCategory(category); \
+  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled_) { \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+        base::debug::TRACE_EVENT_PHASE_BEGIN, \
+        __FILE__, __LINE__, \
+        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 TRACE_EVENT_END0(category, name) \
+  TRACE_EVENT_END1(category, name, NULL, 0)
+#define TRACE_EVENT_END1(category, name, arg1name, arg1val) \
+  TRACE_EVENT_END2(category, name, arg1name, arg1val, NULL, 0)
+#define TRACE_EVENT_END2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static base::debug::TraceCategory* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetCategory(category); \
+  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled_) { \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+        base::debug::TRACE_EVENT_PHASE_END, \
+        __FILE__, __LINE__, \
+        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  }
 
 namespace base {
 
-class ProcessMetrics;
-
 namespace debug {
 
+// Categories allow enabling/disabling of streams of trace events
+class TraceCategory {
+ public:
+  TraceCategory();
+  ~TraceCategory();
+
+  void set(const char* name, bool enabled) {

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

more descriptive name here, probably needs to start with a capital letter, as
this is not a simple accessor:
http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml?showone=Functi...

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

Changed to POD

+    name_ = name;
+    enabled_ = enabled;
+  }
+
+  const char* name() const { return name_; }
+
+  volatile bool enabled_;

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

still ought to wrap this in an accessor,
http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml?showone=Access...

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

Changed to POD

+ protected:
+  const char* name_;
+};
+
+#define TRACE_MAX_NUM_ARGS 2
+
+enum TraceEventPhase {
+  TRACE_EVENT_PHASE_BEGIN,
+  TRACE_EVENT_PHASE_END,
+  TRACE_EVENT_PHASE_INSTANT
+};
+
+// Simple union of values. This is much lighter weight than base::Value, which
+// requires dynamic allocation and a vtable. To keep the trace runtime overhead
+// low, we want constant size storage here.
+class TraceValue {
+ public:
+  enum Type {
+    TRACE_TYPE_UNDEFINED,
+    TRACE_TYPE_BOOL,
+    TRACE_TYPE_UINT,
+    TRACE_TYPE_INT,
+    TRACE_TYPE_DOUBLE,
+    TRACE_TYPE_POINTER,
+    TRACE_TYPE_STRING
+  };
+
+  TraceValue() : type_(TRACE_TYPE_UNDEFINED) {
+    value_.as_uint = 0ull;
+  }
+  TraceValue(bool rhs) : type_(TRACE_TYPE_BOOL) {
+    value_.as_uint = 0ull; // zero all bits

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

why single out a few cases for this nulling?

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

This code simplified / cut, since it is not needed currently. The reason was
that comparison could be done via largest integer type in the union if even
smaller types cleared the storage.

+    value_.as_bool = rhs;
+  }
+  TraceValue(uint64 rhs) : type_(TRACE_TYPE_UINT) {
+    value_.as_uint = rhs;
+  }
+  TraceValue(uint32 rhs) : type_(TRACE_TYPE_UINT) {
+    value_.as_uint = rhs;
+  }
+  TraceValue(uint16 rhs) : type_(TRACE_TYPE_UINT) {
+    value_.as_uint = rhs;
+  }
+  TraceValue(uint8 rhs) : type_(TRACE_TYPE_UINT) {
+    value_.as_uint = rhs;
+  }
+  TraceValue(int64 rhs) : type_(TRACE_TYPE_INT) {
+    value_.as_int = rhs;
+  }
+  TraceValue(int32 rhs) : type_(TRACE_TYPE_INT) {
+    value_.as_int = rhs;
+  }
+  TraceValue(int16 rhs) : type_(TRACE_TYPE_INT) {
+    value_.as_int = rhs;
+  }
+  TraceValue(int8 rhs) : type_(TRACE_TYPE_INT) {
+    value_.as_int = rhs;
+  }
+  TraceValue(double rhs) : type_(TRACE_TYPE_DOUBLE) {
+    value_.as_double = rhs;
+  }
+  TraceValue(const void* rhs) : type_(TRACE_TYPE_POINTER) {
+    value_.as_uint = 0ull; // zero all bits
+    value_.as_pointer = rhs;
+  }
+  TraceValue(const char* rhs) : type_(TRACE_TYPE_STRING) {
+    value_.as_uint = 0ull; // zero all bits
+    value_.as_string = base::strdup(rhs);

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

Sorry, but no.
See comment at
http://codesearch.google.com/codesearch/p?hl=en#OAMlx_jo-ck/src/base/string_u...

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

Done.

+  }
+  TraceValue(const TraceValue& rhs) : type_(TRACE_TYPE_UNDEFINED) {
+    operator=(rhs);
+  }
+  ~TraceValue() {
+    Destroy();
+  }
+
+  TraceValue& operator=(const TraceValue& rhs);
+  bool operator==(const TraceValue& rhs) const;
+  bool operator!=(const TraceValue& rhs) const {
+    return !operator==(rhs);
+  }
+
+  void Destroy();
+
+  void AppendAsJSON(std::string* out) const;
+
+  Type type() const {
+    return type_;
+  }
+  uint64 as_uint() const {
+    return value_.as_uint;
+  }
+  bool as_bool() const {
+    return value_.as_bool;
+  }
+  int64 as_int() const {
+    return value_.as_int;
+  }
+  double as_double() const {
+    return value_.as_double;
+  }
+  const void* as_pointer() const {
+    return value_.as_pointer;
+  }
+  const char* as_string() const {
+    return value_.as_string;
+  }
+
+ private:
+  union Value {
+    bool as_bool;
+    uint64 as_uint;
+    int64 as_int;
+    double as_double;
+    const void* as_pointer;
+    char* as_string;
+  };
+
+  Type type_;
+  Value value_;
+};
+
+// Output records are "Events" and can be obtained via the
+// OutputCallback whenever the tracing system decides to flush. This
+// can happen at any time, on any thread, or you can programatically
+// force it to happen.
+struct TraceEvent {
+  TraceEvent();
+  ~TraceEvent();
+
+  // Serialize event data to JSON
+  static void AppendEventsAsJSON(const std::vector<TraceEvent>& events,
+      size_t start,
+      size_t count,
+      std::string* out);
+  void AppendAsJSON(std::string* out) const;
+
+
+  unsigned long process_id;
+  unsigned long thread_id;
+  TimeTicks timestamp;
+  TraceEventPhase phase;
+  TraceCategory* category;
+  const char* name;
+  const char* arg_names[TRACE_MAX_NUM_ARGS];
+  TraceValue arg_values[TRACE_MAX_NUM_ARGS];
+};
+
+
 class TraceLog {
  public:
-  enum EventType {
-    EVENT_BEGIN,
-    EVENT_END,
-    EVENT_INSTANT
-  };
-
   static TraceLog* GetInstance();
 
-  // Is tracing currently enabled.
-  static bool IsTracing();
-  // Start logging trace events.
-  static bool StartTracing();
-  // Stop logging trace events.
-  static void StopTracing();
-
-  // Log a trace event of (name, type, id) with the optional extra string.
-  void Trace(const std::string& name,
-             EventType type,
-             const void* id,
-             const std::wstring& extra,
-             const char* file,
-             int line);
-  void Trace(const std::string& name,
-             EventType type,
-             const void* id,
-             const std::string& extra,
-             const char* file,
-             int line);
+  // Global enable of tracing. Currently enables all categories or not.
+  // TODO(scheib): Replace with an Enable/DisableCategory() that
+  // implicitly controls the global logging state.
+  void SetEnabled(bool enabled);
+  bool IsEnabled() { return enabled_; }
+
+  float GetBufferPercentFull() const;
+
+  // 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); // takes ownership of cb
+
+  // The trace buffer does not flush dynamically, so when it fills up,
+  // subsequent trace events will be dropped. This callback is generated when
+  // the trace buffer is full.
+  typedef Callback0::Type BufferFullCallback;
+  void SetBufferFullCallback(BufferFullCallback* 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 TRACE_EVENT* macros, don't call this directly.
+  static TraceCategory* GetCategory(const char* name);
+
+  // Called by TRACE_EVENT* macros, don't call this directly.
+  void 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);
+  static void AddTraceEventEtw(TraceEventPhase phase,
+      const char* file, int line,
+      const char* name,
+      const void* id,
+      const char* extra);
+  static void AddTraceEventEtw(TraceEventPhase phase,
+      const char* file, int line,
+      const char* name,
+      const void* id,
+      const std::string& extra) {
+    AddTraceEventEtw(phase, file, line, name, id, extra.c_str());
+  }
+
+  // Exposed for unittesting only, allows resurrecting our
+  // singleton instance post-AtExit processing.
+  static void Resurrect();
 
  private:
   // This allows constructor and destructor to be private and usable only
   // by the Singleton class.
-  friend struct DefaultSingletonTraits<TraceLog>;
+  friend struct StaticMemorySingletonTraits<TraceLog>;
 
   TraceLog();
   ~TraceLog();
-  bool OpenLogFile();
-  void CloseLogFile();
-  bool Start();
-  void Stop();
-  void Heartbeat();
-  void Log(const std::string& msg);
-
+  TraceCategory* GetCategoryInternal(const char* name);
+
+  // TODO(nduca): switch to per-thread trace buffers to reduce thread
+  // synchronization.
+  Lock lock_;
   bool enabled_;
-  FILE* log_file_;
-  base::Lock file_lock_;
-  TimeTicks trace_start_time_;
-  scoped_ptr<base::ProcessMetrics> process_metrics_;
-  RepeatingTimer<TraceLog> timer_;
-};
+  scoped_ptr<OutputCallback> output_callback_;
+  scoped_ptr<BufferFullCallback> buffer_full_callback_;
+  std::vector<TraceEvent> logged_events_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceLog);
+};
+
+namespace internal {
+
+// Used by 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 (category_->enabled_)
+      base::debug::TraceLog::GetInstance()->AddTraceEvent(
+          base::debug::TRACE_EVENT_PHASE_END,
+          file_, line_,
+          category_,
+          name_,
+          NULL, 0, NULL, 0);
+  }
+
+ private:
+  const char* file_;
+  int line_;
+  TraceCategory* category_;
+  const char* name_;
+};
+
+}  // namespace internal
 
 }  // namespace debug
 }  // namespace base
 
-#endif  // defined(OS_WIN)
-
 #endif  // BASE_DEBUG_TRACE_EVENT_H_