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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

typo: automaticlaly

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

[rvargas (doing something else), 2011/02/25 23:38:33]

Is this really going to be the case?.

[nduca, 2011/03/02 04:15:12]

This is a bit of a typo. The real answer is that tracing is off until someone
enables it. That is either an about:gpu user making a recording [big red "Record
now" button that they press] or on windows, a developer connecting with an ETW
event consumer. If neither of those conditions is met, then tracing macros are
equivalent to a check of an enabled flag on a singleton.

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

[brettw, 2011/02/25 18:30:03]

I don't think it's a good idea to leak these generic macro names.

+#define UNIQUE_IDENTIFIER2(a,b) UNIQUE_IDENTIFIER3(a,b) // __LINE__ eval forced

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

Is this forced evaluation of the __LINE__ macro guaranteed to be portable among
preprocessors?

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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

"with one associated argument" -- is this accurate?

+// 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) = \

[brettw, 2011/02/25 18:30:03]

Is this static really necessary? Can you just call GetCategory every time and
avoid the UNIQUE_IDENTIFIER macros?

Keep in mind this expands to the following code.
  static bool initialized = false;
  static TraceCategory* foo;
  if (!initialized) {
    initialized = true;
    foo = base::debug::TraceLog::GetInstance()->GetCategory(category); 
  }

There is a race condition initializing the parameter. This is why we use
Singleton which contains code that avoids this. In your case, it's possible that
the race condition won't matter, but it still seems like a bad idea to do this
in a macro that may be used from multithreaded code.

[nduca, 2011/03/02 04:15:12]

I should probably have been more clear in the code that we understand and
survive gracefully the race condition you mention. While I haven't polished this
implementation completely [we don't handle shutdown quite right but its fixable]
the idea is that a category pointers is itself a  singleton --- while you might
set the category pointer twice, you get back the same pointer both times.



On 2011/02/25 18:30:03, brettw wrote:

+      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, \

[brettw, 2011/02/25 18:30:03]

Indent wrapped lines 4 spaces. Same elsewhere.

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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

Same question here.

+// 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_)) \

[brettw, 2011/02/25 18:30:03]

Multi-line conditions should use {}

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

[brettw, 2011/02/25 18:30:03]

Indent these one char.

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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

The Google C++ style guide says that all reference arguments must be const.
http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml#Reference_Argu...

+      const std::vector<TraceEvent>& events);
+  void AppendAsJSON(std::string& out) const;

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

Same here.

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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

Perhaps a TODO(nduca): here then?

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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

This class isn't supposed to be accessed externally, right? Is there any way of
hiding it, or at least adding a comment to that effect?

+public:

[brettw, 2011/02/25 18:30:03]

Indent these one char.

+  TraceEndOnScopeClose(const char* file, int line,
+      TraceCategory* category,

[brettw, 2011/02/25 18:30:03]

Params should be aligned (should be under the const).

+      const char* name)
+          : file_(file),

[brettw, 2011/02/25 18:30:03]

: should only be indented 4 spaces (4 fewer than now).

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

[Ken Russell (switch to Gerrit), 2011/02/25 00:56:36]

Why are these protected and not private?

+  const char* file_;
+  int line_;
+  TraceCategory* category_;
+  const char* name_;
 };
 
 }  // namespace debug
 }  // namespace base
 
-#endif  // defined(OS_WIN)
-
 #endif  // BASE_DEBUG_TRACE_EVENT_H_