Allow trace event to work with temporary name strings.

This is needed where the name or arg_names may not be available as compile time constants.


BUG=None
TEST=base_unittests --gtest_filter=TraceEvent*

Review URL: http://codereview.chromium.org/7354025

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@93375 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 196 insertions, 78 deletions

diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index 50eec0e..cc8c49c 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -8,6 +8,7 @@
 #include "base/debug/trace_event_win.h"
 #endif
 #include "base/format_macros.h"
+#include "base/memory/ref_counted_memory.h"
 #include "base/process_util.h"
 #include "base/stringprintf.h"
 #include "base/utf_string_conversions.h"
@@ -42,56 +43,12 @@ static int g_category_index = 2; // skip initial 2 error categories
 //
 ////////////////////////////////////////////////////////////////////////////////
 
-void TraceValue::Destroy() {
-  if (type_ == TRACE_TYPE_STRING) {
-    value_.as_string_refptr->Release();
-    value_.as_string_refptr = NULL;
-  }
-  type_ = TRACE_TYPE_UNDEFINED;
-  value_.as_uint = 0ull;
-}
-
-TraceValue& TraceValue::operator=(const TraceValue& rhs) {
-  if (this == &rhs)
-    return *this;
-
-  Destroy();
-
-  type_ = rhs.type_;
-  switch(type_) {
-    case TRACE_TYPE_UNDEFINED:
-      return *this;
-    case TRACE_TYPE_BOOL:
-      value_.as_bool = rhs.value_.as_bool;
-      return *this;
-    case TRACE_TYPE_UINT:
-      value_.as_uint = rhs.value_.as_uint;
-      return *this;
-    case TRACE_TYPE_INT:
-      value_.as_int = rhs.value_.as_int;
-      return *this;
-    case TRACE_TYPE_DOUBLE:
-      value_.as_double = rhs.value_.as_double;
-      return *this;
-    case TRACE_TYPE_POINTER:
-      value_.as_pointer = rhs.value_.as_pointer;
-      return *this;
-    case TRACE_TYPE_STRING:
-      value_.as_string_refptr = rhs.value_.as_string_refptr;
-      value_.as_string_refptr->AddRef();
-      return *this;
-    default:
-      NOTREACHED();
-      return *this;
-  }
-}
-
 void TraceValue::AppendAsJSON(std::string* out) const {
   char temp_string[128];
   std::string::size_type start_pos;
   switch (type_) {
     case TRACE_TYPE_BOOL:
-      *out += as_bool()? "true" : "false";
+      *out += as_bool() ? "true" : "false";
       break;
     case TRACE_TYPE_UINT:
       base::snprintf(temp_string, arraysize(temp_string), "%llu",
@@ -152,6 +109,21 @@ const char* GetPhaseStr(TraceEventPhase phase) {
   }
 }
 
+size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
+
+// Copies |*member| into |*buffer|, sets |*member| to point to this new
+// location, and then advances |*buffer| by the amount written.
+void CopyTraceEventParameter(char** buffer,
+                             const char** member,
+                             const char* end) {
+  if (*member) {
+    size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
+    DCHECK_LE(static_cast<int>(written), end - *buffer);
+    *member = *buffer;
+    *buffer += written;
+  }
+}
+
 }  // namespace
 
 TraceEvent::TraceEvent()
@@ -171,7 +143,8 @@ TraceEvent::TraceEvent(unsigned long process_id,
                        const TraceCategory* category,
                        const char* name,
                        const char* arg1_name, const TraceValue& arg1_val,
-                       const char* arg2_name, const TraceValue& arg2_val)
+                       const char* arg2_name, const TraceValue& arg2_val,
+                       bool copy)
     : process_id_(process_id),
       thread_id_(thread_id),
       timestamp_(timestamp),
@@ -183,6 +156,35 @@ TraceEvent::TraceEvent(unsigned long process_id,
   arg_names_[1] = arg2_name;
   arg_values_[0] = arg1_val;
   arg_values_[1] = arg2_val;
+
+  size_t alloc_size = 0;
+  if (copy) {
+    alloc_size += GetAllocLength(name);
+    alloc_size += GetAllocLength(arg1_name);
+    alloc_size += GetAllocLength(arg2_name);
+  }
+  // We always take a copy of string arg_vals, even if |copy| was not set.
+  if (arg1_val.type() == TraceValue::TRACE_TYPE_STRING)
+    alloc_size += GetAllocLength(arg1_val.as_string());
+  if (arg2_val.type() == TraceValue::TRACE_TYPE_STRING)
+    alloc_size += GetAllocLength(arg2_val.as_string());
+
+  if (alloc_size) {
+    parameter_copy_storage_ = new RefCountedBytes;
+    parameter_copy_storage_->data.resize(alloc_size);
+    char* ptr = reinterpret_cast<char*>(&parameter_copy_storage_->data[0]);
+    const char* end = ptr + alloc_size;
+    if (copy) {
+      CopyTraceEventParameter(&ptr, &name_, end);
+      CopyTraceEventParameter(&ptr, &arg_names_[0], end);
+      CopyTraceEventParameter(&ptr, &arg_names_[1], end);
+    }
+    if (arg_values_[0].type() == TraceValue::TRACE_TYPE_STRING)
+      CopyTraceEventParameter(&ptr, arg_values_[0].as_assignable_string(), end);
+    if (arg_values_[1].type() == TraceValue::TRACE_TYPE_STRING)
+      CopyTraceEventParameter(&ptr, arg_values_[1].as_assignable_string(), end);
+    DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
+  }
 }
 
 TraceEvent::~TraceEvent() {
@@ -342,7 +344,8 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
                             const char* arg1_name, TraceValue arg1_val,
                             const char* arg2_name, TraceValue arg2_val,
                             int threshold_begin_id,
-                            int64 threshold) {
+                            int64 threshold,
+                            bool copy) {
   DCHECK(name);
 #ifdef USE_UNRELIABLE_NOW
   TimeTicks now = TimeTicks::HighResNow();
@@ -379,7 +382,8 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
                    PlatformThread::CurrentId(),
                    now, phase, category, name,
                    arg1_name, arg1_val,
-                   arg2_name, arg2_val));
+                   arg2_name, arg2_val,
+                   copy));
 
     if (logged_events_.size() == kTraceEventBufferSize) {
       buffer_full_callback_copy = buffer_full_callback_;
@@ -410,7 +414,7 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
     tracelog->AddTraceEvent(phase, category, name,
                             "id", id,
                             "extra", extra ? extra : "",
-                            -1, 0);
+                            -1, 0, false);
   }
 }
 
@@ -435,7 +439,7 @@ void TraceEndOnScopeClose::AddEventIfEnabled() {
         p_data_->category,
         p_data_->name,
         NULL, 0, NULL, 0,
-        -1, 0);
+        -1, 0, false);
   }
 }
 
@@ -458,7 +462,7 @@ void TraceEndOnScopeCloseThreshold::AddEventIfEnabled() {
         p_data_->category,
         p_data_->name,
         NULL, 0, NULL, 0,
-        p_data_->threshold_begin_id, p_data_->threshold);
+        p_data_->threshold_begin_id, p_data_->threshold, false);
   }
 }
 
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 2162091..11b8318 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -37,6 +37,21 @@
 // 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.
+//
+//
 // 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
@@ -122,7 +137,15 @@
 #define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \
     arg2_name, arg2_val) \
   INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, false)
+#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, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, true)
 
 // Records a single BEGIN event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
@@ -136,7 +159,15 @@
 #define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, \
     arg2_name, arg2_val) \
   INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, false)
+#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, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, true)
 
 // Records a single END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
@@ -149,7 +180,15 @@
 #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \
     arg2_name, arg2_val) \
   INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, false)
+#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, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, true)
 
 // Time threshold event:
 // Only record the event if the duration is greater than the specified
@@ -195,12 +234,12 @@
 // Implementation detail: internal macro to create static category and add begin
 // event if the category is enabled.
 #define INTERNAL_TRACE_EVENT_ADD( \
-    phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+    phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val, copy) \
   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); \
+        name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, copy); \
   }
 
 // Implementation detail: internal macro to create static category and add begin
@@ -215,7 +254,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, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, false); \
     INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
         INTERNAL_TRACE_EVENT_UID(catstatic), name); \
   }
@@ -233,12 +272,14 @@
       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, 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); \
   }
 
+class RefCountedBytes;
+
 namespace base {
 
 namespace debug {
@@ -310,47 +351,42 @@ class BASE_API TraceValue {
     value_.as_pointer = rhs;
   }
   TraceValue(const char* rhs) : type_(TRACE_TYPE_STRING) {
-    value_.as_string_refptr = new RefCountedString();
-    value_.as_string_refptr->AddRef();
-    DCHECK(value_.as_string_refptr->HasOneRef());
-    value_.as_string_refptr->data = rhs;
-  }
-  TraceValue(const TraceValue& rhs) : type_(TRACE_TYPE_UNDEFINED) {
-    operator=(rhs);
-  }
-  ~TraceValue() {
-    Destroy();
+    value_.as_string = rhs;
   }
 
-  TraceValue& operator=(const TraceValue& rhs);
-
-  void Destroy();
-
   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 {
-    return value_.as_string_refptr->data.c_str();
+    DCHECK_EQ(TRACE_TYPE_STRING, type_);
+    return value_.as_string;
+  }
+  const char** as_assignable_string() {
+    DCHECK_EQ(TRACE_TYPE_STRING, type_);
+    return &value_.as_string;
   }
-
- typedef RefCountedData<std::string> RefCountedString;
 
  private:
   union Value {
@@ -359,7 +395,7 @@ class BASE_API TraceValue {
     int64 as_int;
     double as_double;
     const void* as_pointer;
-    RefCountedString* as_string_refptr;
+    const char* as_string;
   };
 
   Type type_;
@@ -380,7 +416,8 @@ class TraceEvent {
              const TraceCategory* category,
              const char* name,
              const char* arg1_name, const TraceValue& arg1_val,
-             const char* arg2_name, const TraceValue& arg2_val);
+             const char* arg2_name, const TraceValue& arg2_val,
+             bool copy);
   ~TraceEvent();
 
   // Serialize event data to JSON
@@ -401,6 +438,7 @@ class TraceEvent {
   const char* name_;
   const char* arg_names_[kTraceMaxNumArgs];
   TraceValue arg_values_[kTraceMaxNumArgs];
+  scoped_refptr<RefCountedBytes> parameter_copy_storage_;
 };
 
 
@@ -441,13 +479,16 @@ class BASE_API TraceLog {
   // 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,
                     const char* arg1_name, TraceValue arg1_val,
                     const char* arg2_name, TraceValue arg2_val,
                     int threshold_begin_id,
-                    int64 threshold);
+                    int64 threshold,
+                    bool copy);
   static void AddTraceEventEtw(TraceEventPhase phase,
                                const char* name,
                                const void* id,
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index b48260c..6b8f5f9 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -28,6 +28,8 @@ struct JsonKeyValue {
 
 class TraceEventTestFixture : public testing::Test {
  public:
+  // This fixture does not use SetUp() because the fixture must be manually set
+  // up multiple times when testing AtExit. Use ManualTestSetUp for this.
   void ManualTestSetUp();
   void OnTraceDataCollected(
       scoped_refptr<TraceLog::RefCountedString> json_events_str);
@@ -559,5 +561,76 @@ TEST_F(TraceEventTestFixture, AtExit) {
   }
 }
 
+TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
+  // Test that the TRACE_EVENT macros do not deep-copy their string. If they
+  // do so it may indicate a performance regression, but more-over it would
+  // make the DEEP_COPY overloads redundant.
+  ManualTestSetUp();
+
+  std::string name_string("event name");
+
+  TraceLog::GetInstance()->SetEnabled(true);
+  TRACE_EVENT_INSTANT0("category", name_string.c_str());
+
+  // Modify the string in place (a wholesale reassignment may leave the old
+  // string intact on the heap).
+  name_string[0] = '@';
+
+  TraceLog::GetInstance()->SetEnabled(false);
+
+  EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
+  EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
+}
+
+TEST_F(TraceEventTestFixture, DeepCopy) {
+  ManualTestSetUp();
+
+  static const char kOriginalName1[] = "name1";
+  static const char kOriginalName2[] = "name2";
+  static const char kOriginalName3[] = "name3";
+  std::string name1(kOriginalName1);
+  std::string name2(kOriginalName2);
+  std::string name3(kOriginalName3);
+  std::string arg1("arg1");
+  std::string arg2("arg2");
+  std::string val1("val1");
+  std::string val2("val2");
+
+  TraceLog::GetInstance()->SetEnabled(true);
+  TRACE_EVENT_COPY_INSTANT0("category", name1.c_str());
+  TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
+                          arg1.c_str(), 5);
+  TRACE_EVENT_COPY_END2("category", name3.c_str(),
+                        arg1.c_str(), val1.c_str(),
+                        arg2.c_str(), val2.c_str());
+
+  // As per NormallyNoDeepCopy, modify the strings in place.
+  name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';
+
+  TraceLog::GetInstance()->SetEnabled(false);
+
+  EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
+  EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
+  EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));
+
+  DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
+  DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
+  DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
+  ASSERT_TRUE(entry1);
+  ASSERT_TRUE(entry2);
+  ASSERT_TRUE(entry3);
+
+  int i;
+  EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
+  EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
+  EXPECT_EQ(5, i);
+
+  std::string s;
+  EXPECT_TRUE(entry3->GetString("args.arg1", &s));
+  EXPECT_EQ("val1", s);
+  EXPECT_TRUE(entry3->GetString("args.arg2", &s));
+  EXPECT_EQ("val2", s);
+}
+
 }  // namespace debug
 }  // namespace base