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.
 //
 // 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")
@@ skipping 235 matching lines @@
 #define TRACE_EVENT_IF_LONGER_THAN0(threshold_us, category, name) \
     TRACE_EVENT_IF_LONGER_THAN1(threshold_us, category, name, NULL, 0)
 #define TRACE_EVENT_IF_LONGER_THAN1( \
         threshold_us, category, name, arg1_name, arg1_val) \
     TRACE_EVENT_IF_LONGER_THAN2(threshold_us, category, name, \
                            arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_IF_LONGER_THAN2( \
     threshold_us, category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
     INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold_us, \
         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.
 #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 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, \
           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); \
     }
 
 // 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, \
             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;
 
 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_START,
+  TRACE_EVENT_PHASE_FINISH,
   TRACE_EVENT_PHASE_METADATA
 };
 
 // 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,
@@ skipping 115 matching lines @@
   Value value_;
 };
 
 // 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,
+             uint64 extra,
              const char* arg1_name, const TraceValue& arg1_val,
              const char* arg2_name, const TraceValue& arg2_val,
              bool copy);
   ~TraceEvent();
 
   static const char* GetPhaseString(TraceEventPhase phase);
   static TraceEventPhase GetPhase(const char* 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.

[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_;
 };
 
 
 // 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 107 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,
+                    uint64 extra,
                     const char* arg1_name, TraceValue arg1_val,
                     const char* arg2_name, TraceValue arg2_val,
                     int threshold_begin_id,
                     int64 threshold,
                     EventFlags flags);
   static void AddTraceEventEtw(TraceEventPhase phase,
                                const char* name,
                                const void* id,
                                const char* extra);
   static void AddTraceEventEtw(TraceEventPhase phase,
@@ skipping 29 matching lines @@
   // 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_;
 
   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_