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.
 
 #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/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 <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::GetInstance()->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::GetInstance()->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::GetInstance()->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, 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) \

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

If I'm reading this correctly, these static pointers will dangle post-AtExit
processing, as the TraceLog singleton will deallocate all the categories AtExit?
This is worth a warning to the user at least, and is typical for the tradeoffs
between performance and robustness.
A unittest can be used to shed light on the post-AtExit behavior of this, and if
my reading is incorrect, then I'd like to see a test that makes sure this
doesn't regress.
Since the TRACE_EVENT macros are likely to get used by all and sundry, I find it
more likely than not that this will cause intolerable trouble :(.

[scheib, 2011/04/27 21:20:10]

Done. Categories come from a static pool. A test for at exit behavior exists.

+  static base::debug::TraceCategory* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load(\
+      &(TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+        base::debug::TRACE_EVENT_PHASE_BEGIN, \

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

a unittest to validate arguments are not evaluated unless the trace category is
enabled would be an excellent idea for maintainability.

[scheib, 2011/04/27 21:20:10]

Good test, captured in http://crbug.com/80709 can we omit it for the first land?

+        __FILE__, __LINE__, \
+        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+        name, \
+        arg1name, arg1val, \
+        arg2name, arg2val); \
+  } \
+  base::debug::internal::TraceEndOnScopeClose __profileScope ## __LINE ( \
+      __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, 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* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load( \
+      &(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, 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* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load( \
+      &(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, NULL)
+#define TRACE_EVENT_END1(category, name, arg1name, arg1val) \
+  TRACE_EVENT_END2(category, name, arg1name, arg1val, NULL, NULL)
+#define TRACE_EVENT_END2(category, name, arg1name, arg1val, \
+    arg2name, arg2val) \
+  static base::debug::TraceCategory* \
+      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
+      base::debug::TraceLog::GetInstance()->GetCategory(category); \
+  if (base::subtle::Acquire_Load( \
+      &(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
+// 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_;

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

maybe wrap this in an inline accessor used by the macros?

[scheib, 2011/04/27 21:20:10]

Removed, it was not needed. Just a volatile bool now.

+ 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

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

logging system -> tracing system?

[scheib, 2011/04/27 21:20:10]

Done.

+// can happen at any time, on any thread, or you can programatically
+// force it to happen.
+struct TraceEvent {
+  static void AppendAsJSON(std::string* out,

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

one line comment for method purpose and/or usage?

[scheib, 2011/04/27 21:20:10]

Done.

+      const std::vector<TraceEvent>& events,
+      size_t start,
+      size_t count);
+  TraceEvent();
+  ~TraceEvent();
+  void AppendAsJSON(std::string* out) const;
+
+
+  unsigned long processId;

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: process_id, thread_id, arg_names, arg_values

[scheib, 2011/04/27 21:20:10]

Done.

+  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

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

missing colon after TODO, 
nduca->shceib?
Replaced -> Replace
 

[scheib, 2011/04/27 21:20:10]

Done.

+  // implicitly controls the global logging state.

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

control->controls?

[scheib, 2011/04/27 21:20:10]

Done.

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

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

Add a note that this takes ownership of the callback.

[scheib, 2011/04/27 21:20:10]

Done.

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

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

nit: one space only after //

[scheib, 2011/04/27 21:20:10]

Done.

+  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 AddTraceEventEtw(TraceEventPhase phase,
+      const char* file, int line,
+      const char* name,
+      const void* id,
+      const char* extra);
+  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());
+  }
 
  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();
+
+  // TODO(nduca): switch to per-thread tace buffers to reduce thread

[Sigurður Ásgeirsson, 2011/04/15 17:41:45]

tace->trace?

[scheib, 2011/04/27 21:20:10]

Done.

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