trace_event: distinguish between scoped begin/end and global start/finish events

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 are for tracking application performance and resource usage.
 // Macros are provided to track:
 //    Begin and end of function calls
 //    Counters
 //
 // Events are issued against categories. Whereas LOG's
@@ skipping 16 matching lines @@
 // Additional parameters can be associated with an event:
 //   void doSomethingCostly2(int howMuch) {
 //     TRACE_EVENT1("MY_SUBSYSTEM", "doSomethingCostly",
 //         "howMuch", howMuch);
 //     ...
 //   }
 //
 // The trace system will automatically add to this information the
 // current process id, thread id, and a timestamp in microseconds.
 //
+// BEGIN and END events should typically be used in the same scope. To trace

[nduca, 2011/12/01 02:55:26]

typically->clearly state the nesting requirement. Move or copy to the part of
the doc that explains begin/end.

[jbates, 2011/12/01 23:07:50]

Done.

+// an asynchronous procedure such as IPC send/receive, use START and FINISH:
+//   void* ipc_send(...) {
+//     static int send_count = 0;
+//     ++send_count;
+//     TRACE_EVENT_START0("ipc", "message", send_count);
+//   }
+//   void ipc_recv(...) {
+//     static int recv_count = 0;

[jar (doing other things), 2011/12/01 01:47:49]

This is not multi-thread safe.  At first, I thought all you'd lose is an
occasional mis-match... but then I realized that once you had a collision during
the increment, you'd (probably) never re-align.  Have you looked at the cost of
an atomic increment in this scenario?

[nduca, 2011/12/01 02:55:26]

+1, even though its docs, it should be "legitimate."

[jbates, 2011/12/01 23:07:50]

Done.

+//     ++recv_count;
+//     TRACE_EVENT_FINISH0("ipc", "message", send_count);
+//   }
+// The third parameter is a unique ID to match START/FINISH pairs.
+// START and FINISH can occur on any thread of any traced process. Pointers can
+// be used for the ID parameter, and they will be mangled internally so that
+// the same pointer on two different processes will not match. For example:
+//   void* trace_malloc(size) {
+//     void* ptr = malloc(size);
+//     TRACE_EVENT_START0("memory", "malloc", ptr);
+//   }
+//   void trace_free(ptr) {
+//     free(ptr);
+//     TRACE_EVENT_FINISH0("memory", "malloc", ptr);

[jar (doing other things), 2011/12/01 01:47:49]

FYI: If you put the free after the event, then you'd be guaranteed uniqueness
(within a process, for the lifetime of the event).  

This code gives you the moral equivalent of a lock, but uses only TLS (inside
TCMalloc) to get a unique count.  Given the cost of the malloc, I'd bet than an
atomic increment would be much cheaper.  You could then pass along the counter
value as a fully unique selector for the event you are following (much cheaper
than a malloc), and it would probably only be 32 bits, which would be easier to
hash into an int64 (with a 32 bit PID?).

I'd suggest providing functionality to do exactly this, so that users won't have
to write the code that messes with such stuff.

[nduca, 2011/12/01 02:55:26]

I suggest using an example closer to that ReadTransaction class where you put
the START/FINISH in the constructor destructor to avoid triggering malloc/free
type debates.

[jbates, 2011/12/01 23:07:50]

Done.

+//   }
+//
 // Trace event also supports counters, which is a way to track a quantity
 // as it varies over time. Counters are created with the following macro:
 //   TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter", g_myCounterValue);
 //
 // Counters are process-specific. The macro itself can be issued from any
 // thread, however.
 //
 // Sometimes, you want to track two counters at once. You can do this with two
 // counter macros:
 //   TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter0", g_myCounterValue[0]);
@@ skipping 83 matching lines @@
 #include "base/timer.h"
 
 // By default, const char* argument values are assumed to have long-lived scope
 // and will not be copied. Use this macro to force a const char* to be copied.
 #define TRACE_STR_COPY(str) base::debug::TraceValue::StringWithCopy(str)
 
 // 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, \
+        TRACE_EVENT_PHASE_BEGIN, \
         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, \
+        TRACE_EVENT_PHASE_END, \
         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, \
+        TRACE_EVENT_PHASE_INSTANT, \
         name, reinterpret_cast<const void*>(id), extra)
 
 // 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.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT0(category, name) \
     TRACE_EVENT1(category, name, NULL, 0)
 #define TRACE_EVENT1(category, name, arg1_name, arg1_val) \
@@ skipping 22 matching lines @@
 // associated arguments. If the category is not enabled, then this
 // does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_INSTANT0(category, name) \
     TRACE_EVENT_INSTANT1(category, name, NULL, 0)
 #define TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \
     TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
+    INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \
         category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
-        base::debug::TraceLog::EVENT_FLAG_NONE)
+        TRACE_EVENT_FLAG_NONE)
 #define TRACE_EVENT_COPY_INSTANT0(category, name) \
     TRACE_EVENT_COPY_INSTANT1(category, name, NULL, 0)
 #define TRACE_EVENT_COPY_INSTANT1(category, name, arg1_name, arg1_val) \
     TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
+    INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \
         category, name, \
         arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
         arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
-        base::debug::TraceLog::EVENT_FLAG_COPY)
+        TRACE_EVENT_FLAG_COPY)
 
 // 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.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_BEGIN0(category, name) \
     TRACE_EVENT_BEGIN1(category, name, NULL, 0)
 #define TRACE_EVENT_BEGIN1(category, name, arg1_name, arg1_val) \
     TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
+    INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \
         category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
-        base::debug::TraceLog::EVENT_FLAG_NONE)
+        TRACE_EVENT_FLAG_NONE)
 #define TRACE_EVENT_COPY_BEGIN0(category, name) \
     TRACE_EVENT_COPY_BEGIN1(category, name, NULL, 0)
 #define TRACE_EVENT_COPY_BEGIN1(category, name, arg1_name, arg1_val) \
     TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
+    INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \
         category, name, \
         arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
         arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
-        base::debug::TraceLog::EVENT_FLAG_COPY)
+        TRACE_EVENT_FLAG_COPY)
 
 // Records a single END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_END0(category, name) \
     TRACE_EVENT_END1(category, name, NULL, 0)
 #define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \
     TRACE_EVENT_END2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
+    INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
-        base::debug::TraceLog::EVENT_FLAG_NONE)
+        TRACE_EVENT_FLAG_NONE)
 #define TRACE_EVENT_COPY_END0(category, name) \
     TRACE_EVENT_COPY_END1(category, name, NULL, 0)
 #define TRACE_EVENT_COPY_END1(category, name, arg1_name, arg1_val) \
     TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
+    INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, \
         arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
         arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
-        base::debug::TraceLog::EVENT_FLAG_COPY)
+        TRACE_EVENT_FLAG_COPY)
 
 // Time threshold event:
 // Only record the event if the duration is greater than the specified
 // threshold_us (time in microseconds).
 // 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.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_IF_LONGER_THAN0(threshold_us, category, name) \
@@ skipping 18 matching lines @@
 
 // Records the values of a multi-parted counter called "name" immediately.
 // The UI will treat value1 and value2 as parts of a whole, displaying their
 // values as a stacked-bar chart.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_COUNTER2(category, name, value1_name, value1_val, \
         value2_name, value2_val) \
     INTERNAL_TRACE_EVENT_ADD_COUNTER( \
         category, name, value1_name, value1_val, value2_name, value2_val, \
-        base::debug::TraceLog::EVENT_FLAG_NONE)
+        TRACE_EVENT_FLAG_NONE)
 #define TRACE_COPY_COUNTER2(category, name, value1_name, value1_val, \
         value2_name, value2_val) \
     INTERNAL_TRACE_EVENT_ADD_COUNTER( \
         category, name, \
         value1_name, value1_val, \
         value2_name, value2_val, \
-        base::debug::TraceLog::EVENT_FLAG_COPY)
+        TRACE_EVENT_FLAG_COPY)
+
+
+// Records a single START event called "name" immediately, with 0, 1 or 2
+// associated arguments. If the category is not enabled, then this
+// does nothing.
+// - category and name strings must have application lifetime (statics or
+//   literals). They may not include " chars.
+// - |id| is used to match the START event with the FINISH event. It must either
+//   be a pointer or an integer value up to 64 bits. If it's a pointer, the bits
+//   will be xored with a hash of the process ID so that the same pointer on
+//   two different processes will not collide.
+#define TRACE_EVENT_START0(category, name, id) \
+    TRACE_EVENT_START1(category, name, id, NULL, 0)
+#define TRACE_EVENT_START1(category, name, id, arg1_name, arg1_val) \
+    TRACE_EVENT_START2(category, name, id, arg1_name, arg1_val, NULL, 0)
+#define TRACE_EVENT_START2(category, name, id, arg1_name, arg1_val, \
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \
+        category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, \
+        TRACE_EVENT_FLAG_HAS_ID)
+#define TRACE_EVENT_COPY_START0(category, name, id) \
+    TRACE_EVENT_COPY_START1(category, name, id, NULL, 0)
+#define TRACE_EVENT_COPY_START1(category, name, id, arg1_name, arg1_val) \
+    TRACE_EVENT_COPY_START2(category, name, id, arg1_name, arg1_val, NULL, 0)
+#define TRACE_EVENT_COPY_START2(category, name, id, arg1_name, arg1_val, \
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \
+        category, name, id, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY)
+
+// Records a single FINISH event for "name" immediately. If the category
+// is not enabled, then this does nothing.
+#define TRACE_EVENT_FINISH0(category, name, id) \
+    TRACE_EVENT_FINISH1(category, name, id, NULL, 0)
+#define TRACE_EVENT_FINISH1(category, name, id, arg1_name, arg1_val) \
+    TRACE_EVENT_FINISH2(category, name, id, arg1_name, arg1_val, NULL, 0)
+#define TRACE_EVENT_FINISH2(category, name, id, arg1_name, arg1_val, \
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \
+        category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, \
+        TRACE_EVENT_FLAG_HAS_ID)
+#define TRACE_EVENT_COPY_FINISH0(category, name, id) \
+    TRACE_EVENT_COPY_FINISH1(category, name, id, NULL, 0)
+#define TRACE_EVENT_COPY_FINISH1(category, name, id, arg1_name, arg1_val) \
+    TRACE_EVENT_COPY_FINISH2(category, name, id, arg1_name, arg1_val, NULL, 0)
+#define TRACE_EVENT_COPY_FINISH2(category, name, id, arg1_name, arg1_val, \
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \
+        category, name, id, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY)
 
 
 // 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 INTERNAL_TRACE_EVENT_UID3(a,b) \
     trace_event_unique_##a##b
 #define INTERNAL_TRACE_EVENT_UID2(a,b) \
     INTERNAL_TRACE_EVENT_UID3(a,b)
 #define INTERNAL_TRACE_EVENT_UID(name_prefix) \
     INTERNAL_TRACE_EVENT_UID2(name_prefix, __LINE__)
 
 // Implementation detail: internal macro to create static category.
 // - ANNOTATE_BENIGN_RACE, see Thread Safety above.
 #define INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category) \
     static const base::debug::TraceCategory* \
         INTERNAL_TRACE_EVENT_UID(catstatic) = NULL; \
     ANNOTATE_BENIGN_RACE(&INTERNAL_TRACE_EVENT_UID(catstatic), \
                          "trace_event category"); \
     if (!INTERNAL_TRACE_EVENT_UID(catstatic)) \
       INTERNAL_TRACE_EVENT_UID(catstatic) = \
           base::debug::TraceLog::GetCategory(category);
 
-// Implementation detail: internal macro to create static category and add begin
+// Implementation detail: internal macro to create static category and add
 // event if the category is enabled.
 #define INTERNAL_TRACE_EVENT_ADD( \
       phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val, flags) \
     INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
     if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
       base::debug::TraceLog::GetInstance()->AddTraceEvent( \
           phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
-          name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
+          name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
     }
 
 // Implementation detail: internal macro to create static category and
 // add the counter event if it is enabled.
 #define INTERNAL_TRACE_EVENT_ADD_COUNTER( \
       category, name, arg1_name, arg1_val, arg2_name, arg2_val, flags) \
     INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
     if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
       base::debug::TraceLog::GetInstance()->AddCounterEvent( \
           INTERNAL_TRACE_EVENT_UID(catstatic), \
           name, arg1_name, arg1_val, arg2_name, arg2_val, flags); \
     }
 
 // Implementation detail: internal macro to create static category and add begin
 // event if the category is enabled. Also adds the end event when the scope
 // ends.
 #define INTERNAL_TRACE_EVENT_ADD_SCOPED( \
       category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
     INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
     base::debug::internal::TraceEndOnScopeClose \
         INTERNAL_TRACE_EVENT_UID(profileScope); \
     if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
       base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-          base::debug::TRACE_EVENT_PHASE_BEGIN, \
+          TRACE_EVENT_PHASE_BEGIN, \
           INTERNAL_TRACE_EVENT_UID(catstatic), \
-          name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
-          base::debug::TraceLog::EVENT_FLAG_NONE); \
+          name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
+          TRACE_EVENT_FLAG_NONE); \
       INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
           INTERNAL_TRACE_EVENT_UID(catstatic), name); \
     }
 
 // Implementation detail: internal macro to create static category and add begin
 // event if the category is enabled. Also adds the end event when the scope
 // ends. If the elapsed time is < threshold time, the begin/end pair is erased.
 #define INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold, \
       category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
     INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
     base::debug::internal::TraceEndOnScopeCloseThreshold \
         INTERNAL_TRACE_EVENT_UID(profileScope); \
     if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
       int INTERNAL_TRACE_EVENT_UID(begin_event_id) = \
         base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-            base::debug::TRACE_EVENT_PHASE_BEGIN, \
+            TRACE_EVENT_PHASE_BEGIN, \
             INTERNAL_TRACE_EVENT_UID(catstatic), \
-            name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
-            base::debug::TraceLog::EVENT_FLAG_NONE); \
+            name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
+            TRACE_EVENT_FLAG_NONE); \
       INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
           INTERNAL_TRACE_EVENT_UID(catstatic), name, \
           INTERNAL_TRACE_EVENT_UID(begin_event_id), threshold); \
     }
 
+// Implementation detail: internal macro to create static category and add
+// event if the category is enabled.
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID(phase, category, name, id, \
+      arg1_name, arg1_val, arg2_name, arg2_val, flags) \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+    if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
+      base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+          phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
+          name, id, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
+    }
+
 template <typename Type>
 struct StaticMemorySingletonTraits;
 
 namespace base {
 
 class RefCountedString;
 
 namespace debug {
 
 // Categories allow enabling/disabling of streams of trace events
 struct TraceCategory {
   const char* name;
   volatile bool enabled;
 };
 
 const size_t kTraceMaxNumArgs = 2;
 
 // Phase indicates the nature of an event entry. E.g. part of a begin/end pair.
-enum TraceEventPhase {
-  TRACE_EVENT_PHASE_BEGIN,
-  TRACE_EVENT_PHASE_END,
-  TRACE_EVENT_PHASE_INSTANT,
-  TRACE_EVENT_PHASE_METADATA,
-  TRACE_EVENT_PHASE_COUNTER
-};
+typedef char TraceEventPhase;
+#define TRACE_EVENT_PHASE_BEGIN     (base::debug::TraceEventPhase('B'))
+#define TRACE_EVENT_PHASE_END       (base::debug::TraceEventPhase('E'))
+#define TRACE_EVENT_PHASE_INSTANT   (base::debug::TraceEventPhase('I'))
+#define TRACE_EVENT_PHASE_START     (base::debug::TraceEventPhase('S'))
+#define TRACE_EVENT_PHASE_FINISH    (base::debug::TraceEventPhase('F'))
+#define TRACE_EVENT_PHASE_METADATA  (base::debug::TraceEventPhase('M'))
+#define TRACE_EVENT_PHASE_COUNTER   (base::debug::TraceEventPhase('C'))
+
+typedef uint8 TraceEventFlags;
+#define TRACE_EVENT_FLAG_NONE        (base::debug::TraceEventFlags(0))
+#define TRACE_EVENT_FLAG_COPY        (base::debug::TraceEventFlags(1<<0))
+#define TRACE_EVENT_FLAG_HAS_ID      (base::debug::TraceEventFlags(1<<1))
 

[nduca, 2011/12/01 02:55:26]

<3

 // 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 BASE_EXPORT TraceValue {
  public:
   enum Type {
     TRACE_TYPE_UNDEFINED,
     TRACE_TYPE_BOOL,
     TRACE_TYPE_UINT,
     TRACE_TYPE_INT,
@@ skipping 105 matching lines @@
     int64 as_int;
     double as_double;
     const void* as_pointer;
     const char* as_string;
   };
 
   Type type_;
   Value value_;
 };
 
+// TraceID encapsulates an ID that can either be an integer or pointer. Pointers
+// are mangled with the Process ID so that they are unlikely to collide when the
+// same pointer is used on different processes.
+class BASE_EXPORT TraceID {
+ public:
+  TraceID() : data_(NULL) {}
+  TraceID(void* rhs);
+  TraceID(unsigned long long rhs) : data_(static_cast<uint64>(rhs)) {}
+  TraceID(unsigned long rhs) : data_(static_cast<uint64>(rhs)) {}
+  TraceID(unsigned int rhs) : data_(static_cast<uint64>(rhs)) {}
+  TraceID(long long rhs) : data_(static_cast<uint64>(rhs)) {}
+  TraceID(long rhs) : data_(static_cast<uint64>(rhs)) {}
+  TraceID(int rhs) : data_(static_cast<uint64>(rhs)) {}
+
+  uint64 data() const { return data_; }
+
+ private:
+  uint64 data_;
+};
+
 // 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.
 class BASE_EXPORT TraceEvent {
  public:
   TraceEvent();
-  TraceEvent(unsigned long process_id,
-             unsigned long thread_id,
+  TraceEvent(int thread_id,
              TimeTicks timestamp,
              TraceEventPhase phase,
              const TraceCategory* category,
              const char* name,
+             TraceID id,
              const char* arg1_name, const TraceValue& arg1_val,
              const char* arg2_name, const TraceValue& arg2_val,
-             bool copy);
+             TraceEventFlags flags);
   ~TraceEvent();
 
-  static const char* GetPhaseString(TraceEventPhase phase);
-  static TraceEventPhase GetPhase(const char* phase);
+  static char GetPhaseChar(TraceEventPhase phase) {
+    return static_cast<char>(phase);
+  }
+
+  static TraceEventPhase GetPhase(const char* phase) {
+    return static_cast<TraceEventPhase>(*phase);
+  }
 
   // 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;
 
   TimeTicks timestamp() const { return timestamp_; }
 
   // Exposed for unittesting:
 
   const base::RefCountedString* parameter_copy_storage() const {
     return parameter_copy_storage_.get();
   }
 
   const char* name() const { return name_; }
 
  private:
-  unsigned long process_id_;
-  unsigned long thread_id_;
+  // Note: these are ordered by size (largest first) for optimal packing.
   TimeTicks timestamp_;
-  TraceEventPhase phase_;
+  // id_ can be used to store phase-specific data.
+  TraceID id_;
+  TraceValue arg_values_[kTraceMaxNumArgs];
+  const char* arg_names_[kTraceMaxNumArgs];
   const TraceCategory* category_;
   const char* name_;
-  const char* arg_names_[kTraceMaxNumArgs];
-  TraceValue arg_values_[kTraceMaxNumArgs];
   scoped_refptr<base::RefCountedString> parameter_copy_storage_;
+  int thread_id_;
+  TraceEventPhase phase_;
+  TraceEventFlags flags_;
 };
 
 
 // TraceResultBuffer collects and converts trace fragments returned by TraceLog
 // to JSON output.
 class BASE_EXPORT TraceResultBuffer {
  public:
   typedef base::Callback<void(const std::string&)> OutputCallback;
 
   // If you don't need to stream JSON chunks out efficiently, and just want to
@@ skipping 29 matching lines @@
   void Finish();
 
  private:
   OutputCallback output_callback_;
   bool append_comma_;
 };
 
 
 class BASE_EXPORT TraceLog {
  public:
-  // Flags for passing to AddTraceEvent.
-  enum EventFlags {
-    EVENT_FLAG_NONE = 0,
-    EVENT_FLAG_COPY = 1<<0
-  };
-
   static TraceLog* GetInstance();
 
   // Get set of known categories. This can change as new code paths are reached.
   // The known categories are inserted into |categories|.
   void GetKnownCategories(std::vector<std::string>* categories);
 
   // Enable tracing for provided list of categories. If tracing is already
   // enabled, this method does nothing -- changing categories during trace is
   // not supported.
   // If both included_categories and excluded_categories are empty,
@@ skipping 52 matching lines @@
   // Returns the index in the internal vector of the event if it was added, or
   //         -1 if the event was not added.
   // On end events, the return value of the begin event can be specified along
   // with a threshold in microseconds. If the elapsed time between begin and end
   // is less than the threshold, the begin/end event pair is dropped.
   // If |copy| is set, |name|, |arg_name1| and |arg_name2| will be deep copied
   // into the event; see "Memory scoping note" and TRACE_EVENT_COPY_XXX above.
   int AddTraceEvent(TraceEventPhase phase,
                     const TraceCategory* category,
                     const char* name,
+                    TraceID id,
                     const char* arg1_name, TraceValue arg1_val,
                     const char* arg2_name, TraceValue arg2_val,
                     int threshold_begin_id,
                     int64 threshold,
-                    EventFlags flags);
+                    TraceEventFlags flags);
   static void AddTraceEventEtw(TraceEventPhase phase,
                                const char* name,
                                const void* id,
                                const char* extra);
   static void AddTraceEventEtw(TraceEventPhase phase,
                                const char* name,
                                const void* id,
                                const std::string& extra);
 
   // A wrapper around AddTraceEvent used by TRACE_COUNTERx macros
   // that allows only integer values for the counters.
   int AddCounterEvent(const TraceCategory* category,
                       const char* name,
                       const char* arg1_name, int32 arg1_val,
                       const char* arg2_name, int32 arg2_val,
-                      EventFlags flags);
+                      TraceEventFlags flags);
+
+  // Mangle |id| with a hash based on the process ID so that if |id| occurs on
+  // more than one process, it will not collide.
+  uint64 GetIntraProcessID(uint64 id) const { return id ^ process_id_hash_; }

[nduca, 2011/12/01 02:55:26]

Why this versus just tracking id and a bool flag saying "you need to put the
pid", then making the id a string in the json? You could get pretty unlucky in
this scheme, I worry.

[jbates, 2011/12/01 23:07:50]

Sounds good, but sadly I think I would have to double the size of TraceID to do
that :(. With a 64-bit hash, a collision is extremely unlikely. The collision
would have to happen within a set of START/FINISH events of the same
category/name. Seems OK considering there's not much risk?

+
+  int process_id() const { return process_id_; }
 
   // Exposed for unittesting:
 
   // Allows deleting our singleton instance.
   static void DeleteForTesting();
 
   // Allows resurrecting our singleton instance post-AtExit processing.
   static void Resurrect();
 
   // Allow tests to inspect TraceEvents.
   size_t GetEventsSize() const { return logged_events_.size(); }
   const TraceEvent& GetEventAt(size_t index) const {
     DCHECK(index < logged_events_.size());
     return logged_events_[index];
   }
 
+  void SetProcessID(int process_id);
+
  private:
   // This allows constructor and destructor to be private and usable only
   // by the Singleton class.
   friend struct StaticMemorySingletonTraits<TraceLog>;
 
   TraceLog();
   ~TraceLog();
   const TraceCategory* GetCategoryInternal(const char* name);
   void AddCurrentMetadataEvents();
 
   // TODO(nduca): switch to per-thread trace buffers to reduce thread
   // synchronization.
   Lock lock_;
   bool enabled_;
   OutputCallback output_callback_;
   BufferFullCallback buffer_full_callback_;
   std::vector<TraceEvent> logged_events_;
   std::vector<std::string> included_categories_;
   std::vector<std::string> excluded_categories_;
 
-  base::hash_map<PlatformThreadId, std::string> thread_names_;
+  base::hash_map<int, std::string> thread_names_;
+
+  // XORed with TraceID to make it unlikely to collide with other processes.
+  uint64 process_id_hash_;
+
+  int process_id_;
 
   DISALLOW_COPY_AND_ASSIGN(TraceLog);
 };
 
 namespace internal {
 
 // Used by TRACE_EVENTx macro. Do not use directly.
 class BASE_EXPORT TraceEndOnScopeClose {
  public:
   // Note: members of data_ intentionally left uninitialized. See Initialize.
@@ skipping 58 matching lines @@
   Data* p_data_;
   Data data_;
 };
 
 }  // namespace internal
 
 }  // namespace debug
 }  // namespace base
 
 #endif  // BASE_DEBUG_TRACE_EVENT_H_