Add a ConvertableToTraceFormat type to the trace framework.

This patch allows us to have larger objects passed into the trace
framework which, at the point when we output tracing data, will
request they be converted to TraceFormat by calling the
AppendAsTraceFormat method.

BUG=


Review URL: https://chromiumcodereview.appspot.com/13590005

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

4 files changed, 284 insertions, 43 deletions

diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 9f9ec1c..838b2a6d 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -123,6 +123,36 @@
 //                  "arg1", std::string("string will be copied"));
 //
 //
+// Convertable notes:
+// Converting a large data type to a string can be costly. To help with this,
+// the trace framework provides an interface ConvertableToTraceFormat. If you
+// inherit from it and implement the AppendAsTraceFormat method the trace
+// framework will call back to your object to convert a trace output time. This
+// means, if the category for the event is disabled, the conversion will not
+// happen.
+//
+//   class MyData : public base::debug::ConvertableToTraceFormat {
+//    public:
+//     MyData() {}
+//     virtual ~MyData() {}
+//     virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE {
+//       out->append("{\"foo\":1}");
+//     }
+//    private:
+//     DISALLOW_COPY_AND_ASSIGN(MyData);
+//   };
+//
+//   scoped_ptr<MyData> data(new MyData());
+//   TRACE_EVENT1("foo", "bar", "data",
+//                data.PassAs<base::debug::ConvertableToTraceFormat>());
+//
+// The trace framework will take ownership if the passed pointer and it will
+// be free'd when the trace buffer is flushed.
+//
+// Note, we only do the conversion when the buffer is flushed, so the provided
+// data object should not be modified after it's passed to the trace framework.
+//
+//
 // 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
@@ -799,6 +829,7 @@ TRACE_EVENT_API_CLASS_EXPORT extern TRACE_EVENT_API_ATOMIC_WORD g_trace_state2;
 #define TRACE_VALUE_TYPE_POINTER      (static_cast<unsigned char>(5))
 #define TRACE_VALUE_TYPE_STRING       (static_cast<unsigned char>(6))
 #define TRACE_VALUE_TYPE_COPY_STRING  (static_cast<unsigned char>(7))
+#define TRACE_VALUE_TYPE_CONVERTABLE  (static_cast<unsigned char>(8))
 
 // Enum reflecting the scope of an INSTANT event. Must fit within
 // TRACE_EVENT_FLAG_SCOPE_MASK.
@@ -906,9 +937,10 @@ class TraceStringWithCopy {
 #define INTERNAL_DECLARE_SET_TRACE_VALUE(actual_type, \
                                          union_member, \
                                          value_type_id) \
-    static inline void SetTraceValue(actual_type arg, \
-                                     unsigned char* type, \
-                                     unsigned long long* value) { \
+    static inline void SetTraceValue( \
+        actual_type arg, \
+        unsigned char* type, \
+        unsigned long long* value) { \
       TraceValueUnion type_value; \
       type_value.union_member = arg; \
       *type = value_type_id; \
@@ -917,9 +949,10 @@ class TraceStringWithCopy {
 // Simpler form for int types that can be safely casted.
 #define INTERNAL_DECLARE_SET_TRACE_VALUE_INT(actual_type, \
                                              value_type_id) \
-    static inline void SetTraceValue(actual_type arg, \
-                                     unsigned char* type, \
-                                     unsigned long long* value) { \
+    static inline void SetTraceValue( \
+        actual_type arg, \
+        unsigned char* type, \
+        unsigned long long* value) { \
       *type = value_type_id; \
       *value = static_cast<unsigned long long>(arg); \
     }
@@ -969,10 +1002,87 @@ static inline void AddTraceEventWithThreadIdAndTimestamp(
     unsigned long long id,
     int thread_id,
     const base::TimeTicks& timestamp,
+    unsigned char flags,
+    const char* arg1_name,
+    scoped_ptr<base::debug::ConvertableToTraceFormat> arg1_val) {
+  const int num_args = 1;
+  unsigned char arg_types[1] = { TRACE_VALUE_TYPE_CONVERTABLE };
+  scoped_ptr<base::debug::ConvertableToTraceFormat> convertable_values[1];
+  convertable_values[0].reset(arg1_val.release());
+
+  TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
+      phase, category_enabled, name, id, thread_id, timestamp,
+      num_args, &arg1_name, arg_types, NULL, convertable_values, flags);
+}
+
+static inline void AddTraceEvent(
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    unsigned char flags,
+    const char* arg1_name,
+    scoped_ptr<base::debug::ConvertableToTraceFormat> arg1_val) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+  AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
+                                        thread_id, now, flags, arg1_name,
+                                        arg1_val.Pass());
+}
+
+static inline void AddTraceEventWithThreadIdAndTimestamp(
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const base::TimeTicks& timestamp,
+    unsigned char flags,
+    const char* arg1_name,
+    scoped_ptr<base::debug::ConvertableToTraceFormat> arg1_val,
+    const char* arg2_name,
+    scoped_ptr<base::debug::ConvertableToTraceFormat> arg2_val) {
+  const int num_args = 2;
+  unsigned char arg_types[2] =
+      { TRACE_VALUE_TYPE_CONVERTABLE, TRACE_VALUE_TYPE_CONVERTABLE };
+  scoped_ptr<base::debug::ConvertableToTraceFormat> convertable_values[2];
+  convertable_values[0].reset(arg1_val.release());
+  convertable_values[1].reset(arg2_val.release());
+
+  TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
+      phase, category_enabled, name, id, thread_id, timestamp,
+      num_args, &arg1_name, arg_types, NULL, convertable_values, flags);
+}
+
+static inline void AddTraceEvent(
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    unsigned char flags,
+    const char* arg1_name,
+    scoped_ptr<base::debug::ConvertableToTraceFormat> arg1_val,
+    const char* arg2_name,
+    scoped_ptr<base::debug::ConvertableToTraceFormat> arg2_val) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+  AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
+                                        thread_id, now, flags,
+                                        arg1_name, arg1_val.Pass(),
+                                        arg2_name, arg2_val.Pass());
+}
+
+static inline void AddTraceEventWithThreadIdAndTimestamp(
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const base::TimeTicks& timestamp,
     unsigned char flags) {
   TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
       phase, category_enabled, name, id, thread_id, timestamp,
-      kZeroNumArgs, NULL, NULL, NULL, flags);
+      kZeroNumArgs, NULL, NULL, NULL, NULL, flags);
 }
 
 static inline void AddTraceEvent(char phase,
@@ -1003,7 +1113,7 @@ static inline void AddTraceEventWithThreadIdAndTimestamp(
   SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
   TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
       phase, category_enabled, name, id, thread_id, timestamp,
-      num_args, &arg1_name, arg_types, arg_values, flags);
+      num_args, &arg1_name, arg_types, arg_values, NULL, flags);
 }
 
 template<class ARG1_TYPE>
@@ -1042,7 +1152,7 @@ static inline void AddTraceEventWithThreadIdAndTimestamp(
   SetTraceValue(arg2_val, &arg_types[1], &arg_values[1]);
   TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
       phase, category_enabled, name, id, thread_id, timestamp,
-      num_args, arg_names, arg_types, arg_values, flags);
+      num_args, arg_names, arg_types, arg_values, NULL, flags);
 }
 
 template<class ARG1_TYPE, class ARG2_TYPE>
@@ -1088,7 +1198,7 @@ class TRACE_EVENT_API_CLASS_EXPORT TraceEndOnScopeClose {
           TRACE_EVENT_PHASE_END,
           p_data_->category_enabled,
           p_data_->name, kNoEventId,
-          kZeroNumArgs, NULL, NULL, NULL,
+          kZeroNumArgs, NULL, NULL, NULL, NULL,
           TRACE_EVENT_FLAG_NONE);
     }
   }
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index 871ac9c..f525d7c 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -264,17 +264,19 @@ TraceEvent::TraceEvent()
   memset(arg_values_, 0, sizeof(arg_values_));
 }
 
-TraceEvent::TraceEvent(int thread_id,
-                       TimeTicks timestamp,
-                       char phase,
-                       const unsigned char* category_enabled,
-                       const char* name,
-                       unsigned long long id,
-                       int num_args,
-                       const char** arg_names,
-                       const unsigned char* arg_types,
-                       const unsigned long long* arg_values,
-                       unsigned char flags)
+TraceEvent::TraceEvent(
+    int thread_id,
+    TimeTicks timestamp,
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int num_args,
+    const char** arg_names,
+    const unsigned char* arg_types,
+    const unsigned long long* arg_values,
+    scoped_ptr<ConvertableToTraceFormat> convertable_values[],
+    unsigned char flags)
     : timestamp_(timestamp),
       id_(id),
       category_enabled_(category_enabled),
@@ -287,12 +289,17 @@ TraceEvent::TraceEvent(int thread_id,
   int i = 0;
   for (; i < num_args; ++i) {
     arg_names_[i] = arg_names[i];
-    arg_values_[i].as_uint = arg_values[i];
     arg_types_[i] = arg_types[i];
+
+    if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE)
+      convertable_values_[i].reset(convertable_values[i].release());
+    else
+      arg_values_[i].as_uint = arg_values[i];
   }
   for (; i < kTraceMaxNumArgs; ++i) {
     arg_names_[i] = NULL;
     arg_values_[i].as_uint = 0u;
+    convertable_values_[i].reset();
     arg_types_[i] = TRACE_VALUE_TYPE_UINT;
   }
 
@@ -309,6 +316,10 @@ TraceEvent::TraceEvent(int thread_id,
 
   bool arg_is_copy[kTraceMaxNumArgs];
   for (i = 0; i < num_args; ++i) {
+    // No copying of convertable types, we retain ownership.
+    if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
+      continue;
+
     // We only take a copy of arg_vals if they are of type COPY_STRING.
     arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING);
     if (arg_is_copy[i])
@@ -322,10 +333,15 @@ TraceEvent::TraceEvent(int thread_id,
     const char* end = ptr + alloc_size;
     if (copy) {
       CopyTraceEventParameter(&ptr, &name_, end);
-      for (i = 0; i < num_args; ++i)
+      for (i = 0; i < num_args; ++i) {
+        if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
+          continue;
         CopyTraceEventParameter(&ptr, &arg_names_[i], end);
+      }
     }
     for (i = 0; i < num_args; ++i) {
+      if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
+        continue;
       if (arg_is_copy[i])
         CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end);
     }
@@ -333,6 +349,58 @@ TraceEvent::TraceEvent(int thread_id,
   }
 }
 
+TraceEvent::TraceEvent(const TraceEvent& other)
+    : timestamp_(other.timestamp_),
+      id_(other.id_),
+      category_enabled_(other.category_enabled_),
+      name_(other.name_),
+      thread_id_(other.thread_id_),
+      phase_(other.phase_),
+      flags_(other.flags_) {
+  parameter_copy_storage_ = other.parameter_copy_storage_;
+
+  for (int i = 0; i < kTraceMaxNumArgs; ++i) {
+    arg_values_[i] = other.arg_values_[i];
+    arg_names_[i] = other.arg_names_[i];
+    arg_types_[i] = other.arg_types_[i];
+
+    if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
+      convertable_values_[i].reset(
+          const_cast<TraceEvent*>(&other)->convertable_values_[i].release());
+    } else {
+      convertable_values_[i].reset();
+    }
+  }
+}
+
+TraceEvent& TraceEvent::operator=(const TraceEvent& other) {
+  if (this == &other)
+    return *this;
+
+  timestamp_ = other.timestamp_;
+  id_ = other.id_;
+  category_enabled_ = other.category_enabled_;
+  name_ = other.name_;
+  parameter_copy_storage_ = other.parameter_copy_storage_;
+  thread_id_ = other.thread_id_;
+  phase_ = other.phase_;
+  flags_ = other.flags_;
+
+  for (int i = 0; i < kTraceMaxNumArgs; ++i) {
+    arg_values_[i] = other.arg_values_[i];
+    arg_names_[i] = other.arg_names_[i];
+    arg_types_[i] = other.arg_types_[i];
+
+    if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
+      convertable_values_[i].reset(
+          const_cast<TraceEvent*>(&other)->convertable_values_[i].release());
+    } else {
+      convertable_values_[i].reset();
+    }
+  }
+  return *this;
+}
+
 TraceEvent::~TraceEvent() {
 }
 
@@ -403,7 +471,11 @@ void TraceEvent::AppendAsJSON(std::string* out) const {
     *out += "\"";
     *out += arg_names_[i];
     *out += "\":";
-    AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
+
+    if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
+      convertable_values_[i]->AppendAsTraceFormat(out);
+    else
+      AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
   }
   *out += "}";
 
@@ -565,13 +637,7 @@ void TraceSamplingThread::DefaultSampleCallback(TraceBucketData* bucket_data) {
   ExtractCategoryAndName(combined, &category, &name);
   TRACE_EVENT_API_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_SAMPLE,
                                   TraceLog::GetCategoryEnabled(category),
-                                  name,
-                                  0,
-                                  0,
-                                  NULL,
-                                  NULL,
-                                  NULL,
-                                  0);
+                                  name, 0, 0, NULL, NULL, NULL, NULL, 0);
 }
 
 void TraceSamplingThread::GetSamples() {
@@ -1014,20 +1080,23 @@ void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
   }
 }
 
-void TraceLog::AddTraceEvent(char phase,
-                             const unsigned char* category_enabled,
-                             const char* name,
-                             unsigned long long id,
-                             int num_args,
-                             const char** arg_names,
-                             const unsigned char* arg_types,
-                             const unsigned long long* arg_values,
-                             unsigned char flags) {
+void TraceLog::AddTraceEvent(
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int num_args,
+    const char** arg_names,
+    const unsigned char* arg_types,
+    const unsigned long long* arg_values,
+    scoped_ptr<ConvertableToTraceFormat> convertable_values[],
+    unsigned char flags) {
   int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
   base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
   AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
                                         thread_id, now, num_args, arg_names,
-                                        arg_types, arg_values, flags);
+                                        arg_types, arg_values,
+                                        convertable_values, flags);
 }
 
 void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
@@ -1041,6 +1110,7 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     const char** arg_names,
     const unsigned char* arg_types,
     const unsigned long long* arg_values,
+    scoped_ptr<ConvertableToTraceFormat> convertable_values[],
     unsigned char flags) {
   DCHECK(name);
 
@@ -1097,7 +1167,7 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     logged_events_->AddEvent(TraceEvent(thread_id,
         now, phase, category_enabled, name, id,
         num_args, arg_names, arg_types, arg_values,
-        flags));
+        convertable_values, flags));
 
     if (logged_events_->IsFull())
       notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL);
@@ -1184,7 +1254,7 @@ void TraceLog::AddThreadNameMetadataEvents() {
           TimeTicks(), TRACE_EVENT_PHASE_METADATA,
           &g_category_enabled[g_category_metadata],
           "thread_name", trace_event_internal::kNoEventId,
-          num_args, &arg_name, &arg_type, &arg_value,
+          num_args, &arg_name, &arg_type, &arg_value, NULL,
           TRACE_EVENT_FLAG_NONE));
     }
   }
@@ -1244,6 +1314,7 @@ ScopedTrace::ScopedTrace(
         NULL,                       // arg_names
         NULL,                       // arg_types
         NULL,                       // arg_values
+        NULL,                       // convertable_values
         TRACE_EVENT_FLAG_NONE);     // flags
   } else {
     category_enabled_ = NULL;
@@ -1261,6 +1332,7 @@ ScopedTrace::~ScopedTrace() {
         NULL,                    // arg_names
         NULL,                    // arg_types
         NULL,                    // arg_values
+        NULL,                    // convertable values
         TRACE_EVENT_FLAG_NONE);  // flags
   }
 }
diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h
index 7652419..d9f8f1c 100644
--- a/base/debug/trace_event_impl.h
+++ b/base/debug/trace_event_impl.h
@@ -46,6 +46,19 @@ class WaitableEvent;
 
 namespace debug {
 
+// For any argument of type TRACE_VALUE_TYPE_CONVERTABLE the provided
+// class must implement this interface.
+class ConvertableToTraceFormat {
+ public:
+  virtual ~ConvertableToTraceFormat() {}
+
+  // Append the class info to the provided |out| string. The appended
+  // data must be a valid JSON object. Strings must be propertly quoted, and
+  // escaped. There is no processing applied to the content after it is
+  // appended.
+  virtual void AppendAsTraceFormat(std::string* out) const = 0;
+};
+
 const int kTraceMaxNumArgs = 2;
 
 // Output records are "Events" and can be obtained via the
@@ -74,7 +87,10 @@ class BASE_EXPORT TraceEvent {
              const char** arg_names,
              const unsigned char* arg_types,
              const unsigned long long* arg_values,
+             scoped_ptr<ConvertableToTraceFormat> convertable_values[],
              unsigned char flags);
+  TraceEvent(const TraceEvent& other);
+  TraceEvent& operator=(const TraceEvent& other);
   ~TraceEvent();
 
   // Serialize event data to JSON
@@ -106,6 +122,7 @@ class BASE_EXPORT TraceEvent {
   unsigned long long id_;
   TraceValue arg_values_[kTraceMaxNumArgs];
   const char* arg_names_[kTraceMaxNumArgs];
+  scoped_ptr<ConvertableToTraceFormat> convertable_values_[kTraceMaxNumArgs];
   const unsigned char* category_enabled_;
   const char* name_;
   scoped_refptr<base::RefCountedString> parameter_copy_storage_;
@@ -318,6 +335,7 @@ class BASE_EXPORT TraceLog {
                      const char** arg_names,
                      const unsigned char* arg_types,
                      const unsigned long long* arg_values,
+                     scoped_ptr<ConvertableToTraceFormat> convertable_values[],
                      unsigned char flags);
   void AddTraceEventWithThreadIdAndTimestamp(
       char phase,
@@ -330,6 +348,7 @@ class BASE_EXPORT TraceLog {
       const char** arg_names,
       const unsigned char* arg_types,
       const unsigned long long* arg_values,
+      scoped_ptr<ConvertableToTraceFormat> convertable_values[],
       unsigned char flags);
   static void AddTraceEventEtw(char phase,
                                const char* name,
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index 782f07b..c682216 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -1591,6 +1591,46 @@ TEST_F(TraceEventTestFixture, TraceSampling) {
   EXPECT_TRUE(FindNamePhase("Things", "P"));
 }
 
+class MyData : public base::debug::ConvertableToTraceFormat {
+ public:
+  MyData() {}
+  virtual ~MyData() {}
+
+  virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE {
+    out->append("{\"foo\":1}");
+  }
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(MyData);
+};
+
+TEST_F(TraceEventTestFixture, ConvertableTypes) {
+  ManualTestSetUp();
+  TraceLog::GetInstance()->SetEnabled(true, TraceLog::RECORD_UNTIL_FULL);
+
+  scoped_ptr<MyData> data(new MyData());
+  TRACE_EVENT1("foo", "bar", "data",
+               data.PassAs<base::debug::ConvertableToTraceFormat>());
+  EndTraceAndFlush();
+
+  DictionaryValue* dict = FindNamePhase("bar", "B");
+  ASSERT_TRUE(dict);
+
+  const DictionaryValue* args_dict = NULL;
+  dict->GetDictionary("args", &args_dict);
+  ASSERT_TRUE(args_dict);
+
+  const Value* value = NULL;
+  const DictionaryValue* convertable_dict = NULL;
+  EXPECT_TRUE(args_dict->Get("data", &value));
+  ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
+
+  int foo_val;
+  EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
+  EXPECT_EQ(1, foo_val);
+}
+
+
 class TraceEventCallbackTest : public TraceEventTestFixture {
  public:
   virtual void SetUp() OVERRIDE {