Added support to trace_event for passing static string arguments without copy

Occasionally you want to add some static string to a trace, such as the __FILE__ string, but don't want the overhead of a allocation/copy. This change let's you specify those as argument values via a new TraceValue type. You specify const char* types to get the no-copy behavior. std::string types are always copied. To force a const char*, specify TRACE_STR_COPY(str).

TEST=trace_event_unittest.cc

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

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

3 files changed, 183 insertions, 50 deletions

diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index c983df9..8eb774e 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -83,9 +83,10 @@ void TraceValue::AppendAsJSON(std::string* out) const {
       *out += temp_string;
       break;
     case TRACE_TYPE_STRING:
+    case TRACE_TYPE_STATIC_STRING:
       *out += "\"";
       start_pos = out->size();
-      *out += as_string();
+      *out += as_string() ? as_string() : "NULL";
       // replace " character with '
       while ((start_pos = out->find_first_of('\"', start_pos)) !=
              std::string::npos)
@@ -176,10 +177,15 @@ TraceEvent::TraceEvent(unsigned long process_id,
     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)
+
+  bool arg1_is_copy = (arg1_val.type() == TraceValue::TRACE_TYPE_STRING);
+  bool arg2_is_copy = (arg2_val.type() == TraceValue::TRACE_TYPE_STRING);
+
+  // We only take a copy of arg_vals if they are of type string (not static
+  // string), regardless of the |copy| flag.
+  if (arg1_is_copy)
     alloc_size += GetAllocLength(arg1_val.as_string());
-  if (arg2_val.type() == TraceValue::TRACE_TYPE_STRING)
+  if (arg2_is_copy)
     alloc_size += GetAllocLength(arg2_val.as_string());
 
   if (alloc_size) {
@@ -192,9 +198,9 @@ TraceEvent::TraceEvent(unsigned long process_id,
       CopyTraceEventParameter(&ptr, &arg_names_[0], end);
       CopyTraceEventParameter(&ptr, &arg_names_[1], end);
     }
-    if (arg_values_[0].type() == TraceValue::TRACE_TYPE_STRING)
+    if (arg1_is_copy)
       CopyTraceEventParameter(&ptr, arg_values_[0].as_assignable_string(), end);
-    if (arg_values_[1].type() == TraceValue::TRACE_TYPE_STRING)
+    if (arg2_is_copy)
       CopyTraceEventParameter(&ptr, arg_values_[1].as_assignable_string(), end);
     DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
   }
@@ -362,7 +368,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
                             const char* arg2_name, TraceValue arg2_val,
                             int threshold_begin_id,
                             int64 threshold,
-                            bool copy) {
+                            EventFlags flags) {
   DCHECK(name);
 #ifdef USE_UNRELIABLE_NOW
   TimeTicks now = TimeTicks::HighResNow();
@@ -427,7 +433,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
                    now, phase, category, name,
                    arg1_name, arg1_val,
                    arg2_name, arg2_val,
-                   copy));
+                   flags & EVENT_FLAG_COPY));
 
     if (logged_events_.size() == kTraceEventBufferSize) {
       buffer_full_callback_copy = buffer_full_callback_;
@@ -444,22 +450,25 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
                                 const char* name,
                                 const void* id,
                                 const char* extra) {
-  // Legacy trace points on windows called to ETW
 #if defined(OS_WIN)
   TraceEventETWProvider::Trace(name, phase, id, extra);
 #endif
+  INTERNAL_TRACE_EVENT_ADD(phase,
+      "ETW Trace Event", name, "id", id, "extra", TRACE_STR_COPY(extra),
+      base::debug::TraceLog::EVENT_FLAG_NONE);
+}
 
-  // Also add new trace event behavior
-  static const TraceCategory* category = GetCategory("ETW Trace Event");
-  if (category->enabled) {
-    TraceLog* tracelog = TraceLog::GetInstance();
-    if (!tracelog)
-      return;
-    tracelog->AddTraceEvent(phase, category, name,
-                            "id", id,
-                            "extra", extra ? extra : "",
-                            -1, 0, false);
-  }
+void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
+                                const char* name,
+                                const void* id,
+                                const std::string& extra)
+{
+#if defined(OS_WIN)
+  TraceEventETWProvider::Trace(name, phase, id, extra);
+#endif
+  INTERNAL_TRACE_EVENT_ADD(phase,
+      "ETW Trace Event", name, "id", id, "extra", extra,
+      base::debug::TraceLog::EVENT_FLAG_NONE);
 }
 
 void TraceLog::AddCurrentMetadataEvents() {
@@ -474,7 +483,7 @@ void TraceLog::AddCurrentMetadataEvents() {
                      it->first,
                      TimeTicks(), base::debug::TRACE_EVENT_PHASE_METADATA,
                      g_category_metadata, "thread_name",
-                     "name", it->second.c_str(),
+                     "name", it->second,
                      NULL, 0,
                      false));
   }
@@ -501,7 +510,7 @@ void TraceEndOnScopeClose::AddEventIfEnabled() {
         p_data_->category,
         p_data_->name,
         NULL, 0, NULL, 0,
-        -1, 0, false);
+        -1, 0, TraceLog::EVENT_FLAG_NONE);
   }
 }
 
@@ -524,7 +533,8 @@ void TraceEndOnScopeCloseThreshold::AddEventIfEnabled() {
         p_data_->category,
         p_data_->name,
         NULL, 0, NULL, 0,
-        p_data_->threshold_begin_id, p_data_->threshold, false);
+        p_data_->threshold_begin_id, p_data_->threshold,
+        TraceLog::EVENT_FLAG_NONE);
   }
 }
 
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 0fcdaff..380f5e7 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -24,7 +24,7 @@
 // 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);
 //     ...
 //   }
 //
@@ -48,8 +48,19 @@
 // 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 with the _COPY
+//        macros.
+//
+// When are string argument values copied:
+// const char* arg_values are only referenced by default:
+//     TRACE_EVENT1("category", "name",
+//                  "arg1", "literal string is only referenced");
+// Use TRACE_STR_COPY to force copying of a const char*:
+//     TRACE_EVENT1("category", "name",
+//                  "arg1", TRACE_STR_COPY("string will be copied"));
+// std::string arg_values are always copied:
+//     TRACE_EVENT1("category", "name",
+//                  "arg1", std::string("string will be copied"));
 //
 //
 // Thread Safety:
@@ -96,22 +107,26 @@
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #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, \
-      name, reinterpret_cast<const void*>(id), extra);
+      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, \
-      name, reinterpret_cast<const void*>(id), extra);
+      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, \
-      name, reinterpret_cast<const void*>(id), extra);
+      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
@@ -138,7 +153,8 @@
 #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, false)
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
+      base::debug::TraceLog::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) \
@@ -146,7 +162,10 @@
 #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)
+      category, name, \
+      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 BEGIN event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
@@ -160,7 +179,8 @@
 #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, false)
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
+      base::debug::TraceLog::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) \
@@ -168,7 +188,10 @@
 #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)
+      category, name, \
+      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 END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
@@ -181,7 +204,8 @@
 #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, false)
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
+      base::debug::TraceLog::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) \
@@ -189,7 +213,10 @@
 #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)
+      category, name, \
+      arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+      arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+      base::debug::TraceLog::EVENT_FLAG_COPY)
 
 // Time threshold event:
 // Only record the event if the duration is greater than the specified
@@ -235,12 +262,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, copy) \
+    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, copy); \
+        name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
   }
 
 // Implementation detail: internal macro to create static category and add begin
@@ -255,7 +282,8 @@
     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); \
+        name, 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); \
   }
@@ -273,7 +301,8 @@
       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); \
+          name, 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); \
@@ -313,7 +342,8 @@ class BASE_EXPORT TraceValue {
     TRACE_TYPE_INT,
     TRACE_TYPE_DOUBLE,
     TRACE_TYPE_POINTER,
-    TRACE_TYPE_STRING
+    TRACE_TYPE_STRING,
+    TRACE_TYPE_STATIC_STRING
   };
 
   TraceValue() : type_(TRACE_TYPE_UNDEFINED) {
@@ -352,10 +382,27 @@ class BASE_EXPORT TraceValue {
   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;
   }
 
+  static TraceValue StringWithCopy(const char* rhs) {
+    TraceValue value(rhs);
+    if (rhs)
+      value.type_ = TRACE_TYPE_STRING;
+    return value;
+  }
+
+  static TraceValue ForceCopy(const TraceValue& rhs) {
+    TraceValue value(rhs);
+    if (value.type_ == TRACE_TYPE_STATIC_STRING && value.as_string())
+      value.type_ = TRACE_TYPE_STRING;
+    return value;
+  }
+
   void AppendAsJSON(std::string* out) const;
 
   Type type() const {
@@ -382,7 +429,7 @@ class BASE_EXPORT TraceValue {
     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() {
@@ -431,6 +478,14 @@ class TraceEvent {
 
   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_;
@@ -446,6 +501,12 @@ class TraceEvent {
 
 class BASE_EXPORT TraceLog {
  public:
+  // Flags for passing to AddTraceEvent.
+  enum EventFlags {
+    EVENT_FLAG_NONE = 0,
+    EVENT_FLAG_COPY = 1<<0
+  };
+
   static TraceLog* GetInstance();
 
   // Global enable of tracing. Currently enables all categories or not.
@@ -490,7 +551,7 @@ class BASE_EXPORT TraceLog {
                     const char* arg2_name, TraceValue arg2_val,
                     int threshold_begin_id,
                     int64 threshold,
-                    bool copy);
+                    EventFlags flags);
   static void AddTraceEventEtw(TraceEventPhase phase,
                                const char* name,
                                const void* id,
@@ -498,14 +559,20 @@ class BASE_EXPORT TraceLog {
   static void AddTraceEventEtw(TraceEventPhase phase,
                                const char* name,
                                const void* id,
-                               const std::string& extra) {
-    AddTraceEventEtw(phase, name, id, extra.c_str());
-  }
+                               const std::string& extra);
+
+  // Exposed for unittesting:
 
-  // Exposed for unittesting only, allows resurrecting our
-  // singleton instance post-AtExit processing.
+  // 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];
+  }
+
  private:
   // This allows constructor and destructor to be private and usable only
   // by the Singleton class.
@@ -534,6 +601,7 @@ 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_)
@@ -563,6 +631,7 @@ class BASE_EXPORT TraceEndOnScopeClose {
 // 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_)
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index 7217b1d..3fbc777 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -8,6 +8,7 @@
 #include "base/command_line.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
+#include "base/memory/ref_counted_memory.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/process_util.h"
 #include "base/stringprintf.h"
@@ -462,6 +463,59 @@ TEST_F(TraceEventTestFixture, DataCapturedThreshold) {
   EXPECT_NOT_FIND_BE_("4thresholdlong2");
 }
 
+// Test that static strings are not copied.
+TEST_F(TraceEventTestFixture, StaticStringVsString) {
+  ManualTestSetUp();
+  TraceLog* tracer = TraceLog::GetInstance();
+  // Make sure old events are flushed:
+  tracer->SetEnabled(false);
+  EXPECT_EQ(0u, tracer->GetEventsSize());
+
+  {
+    tracer->SetEnabled(true);
+    // Test that string arguments are copied.
+    TRACE_EVENT2("cat", "name1",
+                 "arg1", std::string("argval"), "arg2", std::string("argval"));
+    // Test that static TRACE_STR_COPY string arguments are copied.
+    TRACE_EVENT2("cat", "name2",
+                 "arg1", TRACE_STR_COPY("argval"),
+                 "arg2", TRACE_STR_COPY("argval"));
+    size_t num_events = tracer->GetEventsSize();
+    EXPECT_GT(num_events, 1u);
+    const TraceEvent& event1 = tracer->GetEventAt(num_events - 2);
+    const TraceEvent& event2 = tracer->GetEventAt(num_events - 1);
+    EXPECT_STREQ("name1", event1.name());
+    EXPECT_STREQ("name2", event2.name());
+    EXPECT_TRUE(event1.parameter_copy_storage() != NULL);
+    EXPECT_TRUE(event2.parameter_copy_storage() != NULL);
+    EXPECT_GT(event1.parameter_copy_storage()->size(), 0u);
+    EXPECT_GT(event2.parameter_copy_storage()->size(), 0u);
+    tracer->SetEnabled(false);
+  }
+
+  {
+    tracer->SetEnabled(true);
+    // Test that static literal string arguments are not copied.
+    TRACE_EVENT2("cat", "name1",
+                 "arg1", "argval", "arg2", "argval");
+    // Test that static TRACE_STR_COPY NULL string arguments are not copied.
+    const char* str1 = NULL;
+    const char* str2 = NULL;
+    TRACE_EVENT2("cat", "name2",
+                 "arg1", TRACE_STR_COPY(str1),
+                 "arg2", TRACE_STR_COPY(str2));
+    size_t num_events = tracer->GetEventsSize();
+    EXPECT_GT(num_events, 1u);
+    const TraceEvent& event1 = tracer->GetEventAt(num_events - 2);
+    const TraceEvent& event2 = tracer->GetEventAt(num_events - 1);
+    EXPECT_STREQ("name1", event1.name());
+    EXPECT_STREQ("name2", event2.name());
+    EXPECT_TRUE(event1.parameter_copy_storage() == NULL);
+    EXPECT_TRUE(event2.parameter_copy_storage() == NULL);
+    tracer->SetEnabled(false);
+  }
+}
+
 // Test that data sent from other threads is gathered
 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
   ManualTestSetUp();
@@ -684,8 +738,8 @@ TEST_F(TraceEventTestFixture, DeepCopy) {
   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());
+                        arg1.c_str(), val1,
+                        arg2.c_str(), val2);
 
   // As per NormallyNoDeepCopy, modify the strings in place.
   name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';