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

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 ce52645644575b2d8e788f4c4b88f9008249b485..5019b257cff07cc29530d532a543336775f075ce 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -255,6 +255,62 @@
         category, name, arg1_name, arg1_val, arg2_name, arg2_val)
 

[nduca, 2011/11/17 19:13:06]

Docs in the top of the header?

Can we remove the explicit BEGIN_END macros entirely? The few cases I know that
use them are traceevent bindings to other trace-event frontends [java, webkit]
so they can call TraceEvent::addTraceLog directly.

The benefit of not having the begin/end macros is that we avoid people
inadvertently using begin/end when a start/finish was correct.

[jbates, 2011/11/23 00:41:11]

I think we should remove them, but there are a few users of them as you
mentioned. Let's do it in a future CL.

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

[nduca, 2011/11/17 19:13:06]

Should explain what a start is.

[jbates, 2011/11/23 00:41:11]

Done.

+// - 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 cast
+//   properly to a uint64.
+#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_EXTRA(base::debug::TRACE_EVENT_PHASE_START, \
+        category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, \
+        base::debug::TraceLog::EVENT_FLAG_NONE)
+#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_EXTRA(base::debug::TRACE_EVENT_PHASE_START, \
+        category, name, id, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        base::debug::TraceLog::EVENT_FLAG_COPY)
+
+// Records a single FINISH event for "name" immediately. If the category
+// is not enabled, then this does nothing.
+// - category and name strings must have application lifetime (statics or

[nduca, 2011/11/17 19:13:06]

Should explai what a finish is.

[jbates, 2011/11/23 00:41:11]

Done.

+//   literals). They may not include " chars.
+// - |id| is used to match the START event with the FINISH event. It must cast
+//   properly to a uint64.
+#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_EXTRA(base::debug::TRACE_EVENT_PHASE_FINISH, \
+        category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, \
+        base::debug::TraceLog::EVENT_FLAG_NONE)
+#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_EXTRA(base::debug::TRACE_EVENT_PHASE_FINISH, \
+        category, name, id, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        base::debug::TraceLog::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.
@@ -276,7 +332,7 @@
       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) \
@@ -284,7 +340,7 @@
     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 begin
@@ -299,7 +355,7 @@
       base::debug::TraceLog::GetInstance()->AddTraceEvent( \
           base::debug::TRACE_EVENT_PHASE_BEGIN, \
           INTERNAL_TRACE_EVENT_UID(catstatic), \
-          name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
+          name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
           base::debug::TraceLog::EVENT_FLAG_NONE); \
       INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
           INTERNAL_TRACE_EVENT_UID(catstatic), name); \
@@ -318,13 +374,25 @@
         base::debug::TraceLog::GetInstance()->AddTraceEvent( \
             base::debug::TRACE_EVENT_PHASE_BEGIN, \
             INTERNAL_TRACE_EVENT_UID(catstatic), \
-            name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
+            name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
             base::debug::TraceLog::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_EXTRA(phase, category, name, extra, \
+      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, static_cast<uint64>(extra), \
+          arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
+    }
+
 template <typename Type>
 struct StaticMemorySingletonTraits;
 
@@ -347,6 +415,8 @@ enum TraceEventPhase {
   TRACE_EVENT_PHASE_BEGIN,
   TRACE_EVENT_PHASE_END,
   TRACE_EVENT_PHASE_INSTANT,
+  TRACE_EVENT_PHASE_START,
+  TRACE_EVENT_PHASE_FINISH,
   TRACE_EVENT_PHASE_METADATA
 };
 
@@ -482,12 +552,12 @@ class BASE_EXPORT TraceValue {
 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,
+             uint64 extra,
              const char* arg1_name, const TraceValue& arg1_val,
              const char* arg2_name, const TraceValue& arg2_val,
              bool copy);
@@ -514,15 +584,17 @@ class BASE_EXPORT TraceEvent {
   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.

[jbates, 2011/11/17 01:15:28]

Since I'm adding data to this struct, I took some time to optimize the data
layout for packing and removed the unnecessary process id member.

   TimeTicks timestamp_;
-  TraceEventPhase phase_;
+  // extra_ can be used to store phase-specific data.
+  uint64 extra_;
+  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_;

[jbates, 2011/11/17 01:15:28]

Changed thread_id to int to save 32-bits in the 64-bit builds, because we
eventually cast to int when this is stored in json.

+  TraceEventPhase phase_;
 };
 
 
@@ -650,6 +722,7 @@ class BASE_EXPORT TraceLog {
   int AddTraceEvent(TraceEventPhase phase,
                     const TraceCategory* category,
                     const char* name,
+                    uint64 extra,
                     const char* arg1_name, TraceValue arg1_val,
                     const char* arg2_name, TraceValue arg2_val,
                     int threshold_begin_id,
@@ -699,7 +772,7 @@ class BASE_EXPORT TraceLog {
   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_;
 
   DISALLOW_COPY_AND_ASSIGN(TraceLog);
 };