Trace_event upgrades

base/debug/trace_event.h

Index: base/debug/trace_event.h
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 3eb1f49a90d75989b0efc1cc1b4629500026dc27..3025ccc3188e308af6088bea4039e7316ed2f1bb 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -2,15 +2,42 @@
 // 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 automaticlaly 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_*_LEGACY macros output to ETW.
 
 #ifndef BASE_DEBUG_TRACE_EVENT_H_
 #define BASE_DEBUG_TRACE_EVENT_H_
@@ -18,132 +45,247 @@
 
 #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/scoped_ptr.h"
+#include "base/scoped_vector.h"
+#include "base/atomicops.h"
 #include "base/singleton.h"
-#include "base/synchronization/lock.h"
 #include "base/time.h"
 #include "base/timer.h"
+#include "base/callback.h"
+#include <vector>
+
+#define UNIQUE_IDENTIFIER3(a,b) a##b
+#define UNIQUE_IDENTIFIER2(a,b) UNIQUE_IDENTIFIER3(a,b) // __LINE__ eval forced
+#define UNIQUE_IDENTIFIER(name_prefix) UNIQUE_IDENTIFIER2(name_prefix, __LINE__)
 
-#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( \
+// Records a begin and end event called "name" for the beginning and
+// end of the current scope, with one associated argument. If the
+// category is not enabled, then this does nothing.#
+#define TRACE_EVENT0(category, name) \
+  TRACE_EVENT1(category, name, NULL, NULL)
+#define TRACE_EVENT1(category, name, arg1name, arg1val) \
+  TRACE_EVENT2(category, name, arg1name, arg1val, NULL, NULL)
+#define TRACE_EVENT2(category, name, arg1name, arg1val, arg2name, arg2val) \
+  static base::debug::TraceCategory* UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category);        \
+  if (base::subtle::Acquire_Load(&(UNIQUE_IDENTIFIER(catstatic))->enabled_)) \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+      base::debug::TRACE_EVENT_PHASE_BEGIN, \
+      __FILE__, __LINE__, \
+      UNIQUE_IDENTIFIER(catstatic), \
       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( \
+      arg1name, arg1val, \
+      arg2name, arg2val); \
+  base::debug::TraceEndOnScopeClose __profileScope ## __LINE (__FILE__, \
+      __LINE__, UNIQUE_IDENTIFIER(catstatic), name);
+
+// Records a single event called "name" immediately, with one
+// associated argument. If the category is not enabled, then this
+// does nothing.
+#define TRACE_EVENT_INSTANT0(category, name) \
+  TRACE_EVENT_INSTANT1(category, name, NULL, NULL)
+#define TRACE_EVENT_INSTANT1(category, name, arg1name, arg1val) \
+  TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, NULL, NULL)
+#define TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static base::debug::TraceCategory* UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category);        \
+  if (base::subtle::Acquire_Load(&(UNIQUE_IDENTIFIER(catstatic))->enabled_)) \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+      base::debug::TRACE_EVENT_PHASE_INSTANT, \
+      __FILE__, __LINE__, \
+      UNIQUE_IDENTIFIER(catstatic), \
       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( \
+      arg1name, arg1val, \
+      arg2name, arg2val); \
+
+
+// Use these when you want to issue BEGIN and ENDs across ordinary
+// scope boundaries.
+#define TRACE_EVENT_BEGIN0(category, name) \
+  TRACE_EVENT_BEGIN1(category, name, NULL, NULL)
+#define TRACE_EVENT_BEGIN1(category, name, arg1name, arg1val) \
+  TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, NULL, NULL)
+#define TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static base::debug::TraceCategory* UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category);        \
+  if (base::subtle::Acquire_Load(&(UNIQUE_IDENTIFIER(catstatic))->enabled_)) \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+      base::debug::TRACE_EVENT_PHASE_BEGIN, \
+      __FILE__, __LINE__, \
+      UNIQUE_IDENTIFIER(catstatic), \
       name, \
-      base::debug::TraceLog::EVENT_INSTANT, \
-      reinterpret_cast<const void*>(id), \
-      extra, \
-      __FILE__, \
-      __LINE__)
-#endif  // CHROMIUM_ENABLE_TRACE_EVENT
+      arg1name, arg1val, \
+      arg2name, arg2val);
 
-namespace base {
+#define TRACE_EVENT_END(category, name) \
+  static base::debug::TraceCategory* UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category);        \
+  if (base::subtle::Acquire_Load(&(UNIQUE_IDENTIFIER(catstatic))->enabled_)) \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+      base::debug::TRACE_EVENT_PHASE_END, \
+      __FILE__, __LINE__, \
+      UNIQUE_IDENTIFIER(catstatic), \
+      name, \
+      arg1name, arg1val, \
+      arg2name, arg2val);
+
+
+// LEGACY trace macro support
+#define TRACE_EVENT_BEGIN_LEGACY(name, id, extra) \
+  base::debug::TraceLog::GetInstance()->AddTraceEventLegacy( \
+    base::debug::TRACE_EVENT_PHASE_BEGIN, \
+    __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
 
-class ProcessMetrics;
+#define TRACE_EVENT_END_LEGACY(name, id, extra) \
+  base::debug::TraceLog::GetInstance()->AddTraceEventLegacy( \
+    base::debug::TRACE_EVENT_PHASE_END, \
+    __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+
+#define TRACE_EVENT_INSTANT_LEGACY(name, id, extra) \
+  base::debug::TraceLog::GetInstance()->AddTraceEventLegacy( \
+    base::debug::TRACE_EVENT_PHASE_INSTANT, \
+    __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+
+namespace base {
 
 namespace debug {
 
+// 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 {
+  TRACE_EVENT_PHASE_BEGIN,
+  TRACE_EVENT_PHASE_END,
+  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;
+  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:
-  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(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 TRACE_EVENT* macros, don't call this directly.
+  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* arg1name, const char* arg1val,
+      const char* arg2name, const char* arg2val);
+  void AddTraceEventLegacy(TraceEventPhase phase,
+      const char* file, int line,
+      const char* name,
+      const void* id,
+      const char* extra);
 
  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);
+  void FlushWithLockAlreadyHeld();
 
+  // Guards access to everything right now. If I can get this working,
+  // there are a ton of things we can 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_;
+  ScopedVector<TraceCategory> categories_;
+  scoped_ptr<OutputCallback> output_callback_;
+  std::vector<TraceEvent> logged_events_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceLog);
+};
+
+
+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_))
+      base::debug::TraceLog::GetInstance()->AddTraceEvent(
+          base::debug::TRACE_EVENT_PHASE_END,
+          file_, line_,
+          category_,
+          name_,
+          NULL, NULL, NULL, NULL);
+  }
+protected:
+  const char* file_;
+  int line_;
+  TraceCategory* category_;
+  const char* name_;
 };
 
 }  // namespace debug
 }  // namespace base
 
-#endif  // defined(OS_WIN)
-
 #endif  // BASE_DEBUG_TRACE_EVENT_H_