Added support to trace_event for passing static string arguments without copy

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")
 //
 // 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());
+//         "howMuch", howMuch);
 //     ...
 //   }
 //
 // The trace system will automatically add to this information the
 // current process id, thread id, and a timestamp in microseconds.
 //
 // 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.
 //
 //
 // Memory scoping note:
 // Tracing copies the pointers, not the string content, of the strings passed
 // in for category, name, and arg_names.  Thus, the following code will
 // cause problems:
 //     char* str = strdup("impprtantName");
 //     TRACE_EVENT_INSTANT0("SUBSYSTEM", str);  // BAD!
 //     free(str);                   // Trace system now has dangling pointer
 //
 // To avoid this issue with the |name| and |arg_name| parameters, use the
 // TRACE_EVENT_COPY_XXX overloads of the macros at additional runtime overhead.
 // Notes: The category must always be in a long-lived char* (i.e. static const).
-//        The |arg_values|, when used, are always deep copied and so never have
-//        this restriction.
+//        The |arg_values|, when used, are always deep copied unless type is
+//        const char*, so never have this restriction.
+//
+// const char* arg_values are referenced:
+//     TRACE_EVENT1("category", "event1",

[John Grabowski, 2011/08/30 18:13:38]

Comment should have COPY in the name (2 spots)

+//                  "arg1", "literal string is only referenced");
+// std::string arg_values are copied:
+//     TRACE_EVENT1("category", "event2",

[John Grabowski, 2011/08/30 18:13:38]

This actually does not work for us.  We convert some string types to const char*
but still need them copied.  Will send details in email.

+//                  "arg1", std::string("string will be copied"));
 //
 //
 // Thread Safety:
 // A thread safe singleton and mutex are used for thread safety. Category
 // enabled flags are used to limit the performance impact when the system
 // is not enabled.
 //
 // TRACE_EVENT macros first cache a pointer to a category. The categories are
 // statically allocated and safe at all times, even after exit. Fetching a
 // category is protected by the TraceLog::lock_. Multiple threads initializing
@@ skipping 29 matching lines @@
 #include "base/callback.h"
 #include "base/hash_tables.h"
 #include "base/memory/singleton.h"
 #include "base/string_util.h"
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #include "base/timer.h"
 
 // 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, \
-      name, reinterpret_cast<const void*>(id), extra);
+  do { \
+    INTERNAL_TRACE_EVENT_ETW(name, \
+        base::debug::TRACE_EVENT_PHASE_BEGIN, id, extra); \
+    TRACE_EVENT_BEGIN2("ETW Trace Event", name, \
+        "id", reinterpret_cast<const void*>(id), "extra", extra) \
+  } while(0)

[scheib, 2011/08/30 16:16:02]

Sorry, I'm confused why the changes were needed here? Also, it appears that the
legacy trace points are being discarded on non windows platforms? Aren't they
still handy to have? E.g. the events that come from V8 via webkit
(webkitclient_impl.cc)?

[jbates, 2011/08/30 17:01:51]

The behavior should be the same as before (unless I've made a mistake). This was
just changed to reuse our existing macros, since our macros now support
std::string arguments. TraceLog::AddTraceEventEtw converted std::string to const
char*. Instead, these macros just pass through whether it's std::string or const
char*, since we now support both.

 
 #define TRACE_EVENT_END_ETW(name, id, extra) \
-  base::debug::TraceLog::AddTraceEventEtw( \
-      base::debug::TRACE_EVENT_PHASE_END, \
-      name, reinterpret_cast<const void*>(id), extra);
+  do { \
+    INTERNAL_TRACE_EVENT_ETW(name, \
+        base::debug::TRACE_EVENT_PHASE_END, id, extra); \
+    TRACE_EVENT_END2("ETW Trace Event", name, \
+        "id", reinterpret_cast<const void*>(id), "extra", extra) \
+  } while(0)
 
 #define TRACE_EVENT_INSTANT_ETW(name, id, extra) \
-  base::debug::TraceLog::AddTraceEventEtw( \
-      base::debug::TRACE_EVENT_PHASE_INSTANT, \
-      name, reinterpret_cast<const void*>(id), extra);
+  do { \
+    INTERNAL_TRACE_EVENT_ETW(name, \
+        base::debug::TRACE_EVENT_PHASE_INSTANT, id, extra); \
+    TRACE_EVENT_INSTANT2("ETW Trace Event", name, \
+        "id", reinterpret_cast<const void*>(id), "extra", extra) \
+  } while(0)
 
 // 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) \
   TRACE_EVENT2(category, name, arg1_name, arg1_val, NULL, 0)
@@ skipping 147 matching lines @@
     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, false); \
     INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
         INTERNAL_TRACE_EVENT_UID(catstatic), name, \
         INTERNAL_TRACE_EVENT_UID(begin_event_id), threshold); \
   }
 
+// Implementation detail: support macro for windows ETW style tracing.
+#if defined(OS_WIN)
+#define INTERNAL_TRACE_EVENT_ETW(name, phase, id, extra) \
+  TraceEventETWProvider::Trace( \
+      name, phase, reinterpret_cast<const void*>(id), extra)
+#else
+#define INTERNAL_TRACE_EVENT_ETW(name, phase, id, extra)
+#endif
+
 namespace base {
 
 class RefCountedString;
 
 namespace debug {
 
 // Categories allow enabling/disabling of streams of trace events
 struct TraceCategory {
   const char* name;
   volatile bool enabled;
@@ skipping 14 matching lines @@
 // 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,
     TRACE_TYPE_DOUBLE,
     TRACE_TYPE_POINTER,
-    TRACE_TYPE_STRING
+    TRACE_TYPE_STRING,
+    TRACE_TYPE_STATIC_STRING
   };
 
   TraceValue() : type_(TRACE_TYPE_UNDEFINED) {
     value_.as_uint = 0ull;
   }
   TraceValue(bool rhs) : type_(TRACE_TYPE_BOOL) {
     value_.as_bool = rhs;
   }
   TraceValue(uint64 rhs) : type_(TRACE_TYPE_UINT) {
     value_.as_uint = rhs;
@@ skipping 18 matching lines @@
   }
   TraceValue(int8 rhs) : type_(TRACE_TYPE_INT) {
     value_.as_int = rhs;
   }
   TraceValue(double rhs) : type_(TRACE_TYPE_DOUBLE) {
     value_.as_double = rhs;
   }
   TraceValue(const void* rhs) : type_(TRACE_TYPE_POINTER) {
     value_.as_pointer = rhs;
   }
-  TraceValue(const char* rhs) : type_(TRACE_TYPE_STRING) {
+  TraceValue(const std::string& rhs) : type_(TRACE_TYPE_STRING) {
+    value_.as_string = rhs.c_str();
+  }
+  TraceValue(const char* rhs) : type_(TRACE_TYPE_STATIC_STRING) {
     value_.as_string = rhs;
   }
 
   void AppendAsJSON(std::string* out) const;
 
   Type type() const {
     return type_;
   }
   uint64 as_uint() const {
     DCHECK_EQ(TRACE_TYPE_UINT, type_);
     return value_.as_uint;
   }
   bool as_bool() const {
     DCHECK_EQ(TRACE_TYPE_BOOL, type_);
     return value_.as_bool;
   }
   int64 as_int() const {
     DCHECK_EQ(TRACE_TYPE_INT, type_);
     return value_.as_int;
   }
   double as_double() const {
     DCHECK_EQ(TRACE_TYPE_DOUBLE, type_);
     return value_.as_double;
   }
   const void* as_pointer() const {
     DCHECK_EQ(TRACE_TYPE_POINTER, type_);
     return value_.as_pointer;
   }
   const char* as_string() const {
-    DCHECK_EQ(TRACE_TYPE_STRING, type_);
+    DCHECK(type_ == TRACE_TYPE_STRING || type_ == TRACE_TYPE_STATIC_STRING);
     return value_.as_string;
   }
   const char** as_assignable_string() {
     DCHECK_EQ(TRACE_TYPE_STRING, type_);
     return &value_.as_string;
   }
 
  private:
   union Value {
     bool as_bool;
@@ skipping 28 matching lines @@
 
   // 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_;
   TimeTicks timestamp_;
   TraceEventPhase phase_;
   const TraceCategory* category_;
   const char* name_;
   const char* arg_names_[kTraceMaxNumArgs];
   TraceValue arg_values_[kTraceMaxNumArgs];
   scoped_refptr<base::RefCountedString> parameter_copy_storage_;
@@ skipping 40 matching lines @@
   // 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,
                     const char* arg1_name, TraceValue arg1_val,
                     const char* arg2_name, TraceValue arg2_val,
                     int threshold_begin_id,
                     int64 threshold,
                     bool copy);
-  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) {
-    AddTraceEventEtw(phase, name, id, extra.c_str());
+
+  // Exposed for unittesting:
+
+  // 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];
   }
 
-  // Exposed for unittesting only, allows resurrecting our
-  // singleton instance post-AtExit processing.
-  static void Resurrect();
-
  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_;
 
   base::hash_map<PlatformThreadId, 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.
   TraceEndOnScopeClose() : p_data_(NULL) {}
   ~TraceEndOnScopeClose() {
     if (p_data_)
       AddEventIfEnabled();
   }
 
   void Initialize(const TraceCategory* category,
                   const char* name);
 
  private:
   // Add the end event if the category is still enabled.
   void AddEventIfEnabled();
 
   // This Data struct workaround is to avoid initializing all the members
   // in Data during construction of this object, since this object is always
   // constructed, even when tracing is disabled. If the members of Data were
   // members of this class instead, compiler warnings occur about potential
   // uninitialized accesses.
   struct Data {
     const TraceCategory* category;
     const char* name;
   };
   Data* p_data_;
   Data data_;
 };
 
 // Used by TRACE_EVENTx macro. Do not use directly.
 class BASE_EXPORT TraceEndOnScopeCloseThreshold {
  public:
+  // Note: members of data_ intentionally left uninitialized. See Initialize.
   TraceEndOnScopeCloseThreshold() : p_data_(NULL) {}
   ~TraceEndOnScopeCloseThreshold() {
     if (p_data_)
       AddEventIfEnabled();
   }
 
   // Called by macros only when tracing is enabled at the point when the begin
   // event is added.
   void Initialize(const TraceCategory* category,
                   const char* name,
@@ skipping 18 matching lines @@
   Data* p_data_;
   Data data_;
 };
 
 }  // namespace internal
 
 }  // namespace debug
 }  // namespace base
 
 #endif  // BASE_DEBUG_TRACE_EVENT_H_