Add snapshots to trace_event object model

Trace event had a partially implemented object model, having an OBJECT_CREATED
and OBJECT_DELETED api. This patch:
- Adds an OBJECT_SNAPSHOT API so that object state can be associated with a
  given ID

- Allows IDs to be non-mangled. Objects are process-specific, so they dont need
  mangling. Removal of mangling makes it possible for state snapshots to
  reference objects by their ID without having to mangle those references.

- Properly puts 0x-prefixes in front of hex-dumped numbers so that IDs put into
  trace event come out in the same way.

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

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

4 files changed, 138 insertions, 66 deletions

diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 628383f..366f4ac 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -205,6 +205,11 @@
 #define TRACE_ID_MANGLE(id) \
     trace_event_internal::TraceID::ForceMangle(id)
 
+// By default, pointers are mangled with the Process ID in TRACE_EVENT_ASYNC
+// macros. Use this macro to prevent Process ID mangling.
+#define TRACE_ID_DONT_MANGLE(id) \
+    trace_event_internal::TraceID::DontMangle(id)
+
 // 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.
@@ -641,15 +646,20 @@
         category_group, name, id, TRACE_EVENT_FLAG_COPY, \
         arg1_name, arg1_val, arg2_name, arg2_val)
 
-// Macros to track the life time of arbitratry client objects.
+// Macros to track the life time and value of arbitratry client objects.
 // See also TraceTrackableObject.
 #define TRACE_EVENT_OBJECT_CREATED_WITH_ID(category_group, name, id) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_CREATE_OBJECT, \
-        category_group, name, id, TRACE_EVENT_FLAG_NONE)
+        category_group, name, TRACE_ID_DONT_MANGLE(id), TRACE_EVENT_FLAG_NONE)
+
+#define TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(category_group, name, id, snapshot) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_SNAPSHOT_OBJECT, \
+        category_group, name, TRACE_ID_DONT_MANGLE(id), TRACE_EVENT_FLAG_NONE,\
+        "snapshot", snapshot)
 
 #define TRACE_EVENT_OBJECT_DELETED_WITH_ID(category_group, name, id) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_DELETE_OBJECT, \
-        category_group, name, id, TRACE_EVENT_FLAG_NONE)
+        category_group, name, TRACE_ID_DONT_MANGLE(id), TRACE_EVENT_FLAG_NONE)
 
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -826,6 +836,7 @@ TRACE_EVENT_API_CLASS_EXPORT extern TRACE_EVENT_API_ATOMIC_WORD g_trace_state2;
 #define TRACE_EVENT_PHASE_COUNTER  ('C')
 #define TRACE_EVENT_PHASE_SAMPLE  ('P')
 #define TRACE_EVENT_PHASE_CREATE_OBJECT ('N')
+#define TRACE_EVENT_PHASE_SNAPSHOT_OBJECT ('O')
 #define TRACE_EVENT_PHASE_DELETE_OBJECT ('D')
 
 // Flags for changing the behavior of TRACE_EVENT_API_ADD_TRACE_EVENT.
@@ -866,32 +877,55 @@ const int kZeroNumArgs = 0;
 const unsigned long long kNoEventId = 0;
 
 // TraceID encapsulates an ID that can either be an integer or pointer. Pointers
-// are mangled with the Process ID so that they are unlikely to collide when the
-// same pointer is used on different processes.
+// are by default mangled with the Process ID so that they are unlikely to
+// collide when the same pointer is used on different processes.
 class TraceID {
  public:
+  class DontMangle {
+   public:
+    explicit DontMangle(void* id)
+        : data_(static_cast<unsigned long long>(
+              reinterpret_cast<unsigned long>(id))) {}
+    explicit DontMangle(unsigned long long id) : data_(id) {}
+    explicit DontMangle(unsigned long id) : data_(id) {}
+    explicit DontMangle(unsigned int id) : data_(id) {}
+    explicit DontMangle(unsigned short id) : data_(id) {}
+    explicit DontMangle(unsigned char id) : data_(id) {}
+    explicit DontMangle(long long id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit DontMangle(long id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit DontMangle(int id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit DontMangle(short id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit DontMangle(signed char id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    unsigned long long data() const { return data_; }
+   private:
+    unsigned long long data_;
+  };
+
   class ForceMangle {
-    public:
-     explicit ForceMangle(unsigned long long id) : data_(id) {}
-     explicit ForceMangle(unsigned long id) : data_(id) {}
-     explicit ForceMangle(unsigned int id) : data_(id) {}
-     explicit ForceMangle(unsigned short id) : data_(id) {}
-     explicit ForceMangle(unsigned char id) : data_(id) {}
-     explicit ForceMangle(long long id)
-         : data_(static_cast<unsigned long long>(id)) {}
-     explicit ForceMangle(long id)
-         : data_(static_cast<unsigned long long>(id)) {}
-     explicit ForceMangle(int id)
-         : data_(static_cast<unsigned long long>(id)) {}
-     explicit ForceMangle(short id)
-         : data_(static_cast<unsigned long long>(id)) {}
-     explicit ForceMangle(signed char id)
-         : data_(static_cast<unsigned long long>(id)) {}
-
-     unsigned long long data() const { return data_; }
-
-    private:
-     unsigned long long data_;
+   public:
+    explicit ForceMangle(unsigned long long id) : data_(id) {}
+    explicit ForceMangle(unsigned long id) : data_(id) {}
+    explicit ForceMangle(unsigned int id) : data_(id) {}
+    explicit ForceMangle(unsigned short id) : data_(id) {}
+    explicit ForceMangle(unsigned char id) : data_(id) {}
+    explicit ForceMangle(long long id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit ForceMangle(long id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit ForceMangle(int id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit ForceMangle(short id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    explicit ForceMangle(signed char id)
+        : data_(static_cast<unsigned long long>(id)) {}
+    unsigned long long data() const { return data_; }
+   private:
+    unsigned long long data_;
   };
 
   TraceID(const void* id, unsigned char* flags)
@@ -902,6 +936,8 @@ class TraceID {
   TraceID(ForceMangle id, unsigned char* flags) : data_(id.data()) {
     *flags |= TRACE_EVENT_FLAG_MANGLE_ID;
   }
+  TraceID(DontMangle id, unsigned char* flags) : data_(id.data()) {
+  }
   TraceID(unsigned long long id, unsigned char* flags)
       : data_(id) { (void)flags; }
   TraceID(unsigned long id, unsigned char* flags)
@@ -1213,11 +1249,16 @@ class TRACE_EVENT_API_CLASS_EXPORT TraceEndOnScopeClose {
     // Only called when p_data_ is non-null.
     if (*p_data_->category_group_enabled) {
       TRACE_EVENT_API_ADD_TRACE_EVENT(
-          TRACE_EVENT_PHASE_END,
-          p_data_->category_group_enabled,
-          p_data_->name, kNoEventId,
-          kZeroNumArgs, NULL, NULL, NULL, NULL,
-          TRACE_EVENT_FLAG_NONE);
+          TRACE_EVENT_PHASE_END,            // phase
+          p_data_->category_group_enabled,  // category enabled
+          p_data_->name,                    // name
+          kNoEventId,                       // id
+          kZeroNumArgs,                     // num_args
+          NULL,                             // arg_names
+          NULL,                             // arg_types
+          NULL,                             // arg_values
+          NULL,                             // convertable_values
+          TRACE_EVENT_FLAG_NONE);           // flags
     }
   }
 
@@ -1275,6 +1316,10 @@ template<typename IDType> class TraceScopedTrackableObject {
     TRACE_EVENT_OBJECT_CREATED_WITH_ID(category_group_, name_, id_);
   }
 
+  template <typename ArgType> void snapshot(ArgType snapshot) {
+    TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(category_group_, name_, id_, snapshot);
+  }
+
   ~TraceScopedTrackableObject() {
     TRACE_EVENT_OBJECT_DELETED_WITH_ID(category_group_, name_, id_);
   }
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index 04a1529..9a24abe 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -452,7 +452,7 @@ void TraceEvent::AppendValueAsJSON(unsigned char type,
     case TRACE_VALUE_TYPE_POINTER:
       // JSON only supports double and int numbers.
       // So as not to lose bits from a 64-bit pointer, output as a hex string.
-      StringAppendF(out, "\"%" PRIx64 "\"", static_cast<uint64>(
+      StringAppendF(out, "\"0x%" PRIx64 "\"", static_cast<uint64>(
                                      reinterpret_cast<intptr_t>(
                                      value.as_pointer)));
       break;
@@ -509,7 +509,7 @@ void TraceEvent::AppendAsJSON(std::string* out) const {
   // If id_ is set, print it out as a hex string so we don't loose any
   // bits (it might be a 64-bit pointer).
   if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
-    StringAppendF(out, ",\"id\":\"%" PRIx64 "\"", static_cast<uint64>(id_));
+    StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));
 
   // Instant events also output their scope.
   if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index ea3a072..805c4dc 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -41,9 +41,11 @@ struct JsonKeyValue {
   CompareOp op;
 };
 
-static int kThreadId = 42;
-static int kAsyncId = 5;
-static const char kAsyncIdStr[] = "5";
+const int kThreadId = 42;
+const int kAsyncId = 5;
+const char kAsyncIdStr[] = "0x5";
+const int kAsyncId2 = 6;
+const char kAsyncId2Str[] = "0x6";
 
 class TraceEventTestFixture : public testing::Test {
  public:
@@ -395,16 +397,19 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
 
     TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
         "TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
-        kAsyncId + 1, kThreadId, 34567);
+        kAsyncId2, kThreadId, 34567);
     TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("all",
         "TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call",
-        kAsyncId + 1, kThreadId, 45678);
+        kAsyncId2, kThreadId, 45678);
 
     TRACE_EVENT_OBJECT_CREATED_WITH_ID("all", "tracked object 1", 0x42);
+    TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
+        "all", "tracked object 1", 0x42, "hello");
     TRACE_EVENT_OBJECT_DELETED_WITH_ID("all", "tracked object 1", 0x42);
 
     TraceScopedTrackableObject<int> trackable("all", "tracked object 2",
                                               0x2128506);
+    trackable.snapshot("world");
   } // Scope close causes TRACE_EVENT0 etc to send their END events.
 
   if (task_complete_event)
@@ -427,7 +432,7 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
   {
     std::string str_val;
     EXPECT_TRUE(item && item->GetString("args.id", &str_val));
-    EXPECT_STREQ("1122", str_val.c_str());
+    EXPECT_STREQ("0x1122", str_val.c_str());
   }
   EXPECT_SUB_FIND_("extrastring1");
   EXPECT_FIND_("TRACE_EVENT_END_ETW call");
@@ -601,7 +606,7 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
   {
     std::string id;
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ("319009", id);
+    EXPECT_EQ("0x319009", id);
 
     std::string ph;
     EXPECT_TRUE((item && item->GetString("ph", &ph)));
@@ -616,7 +621,7 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
   {
     std::string id;
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ("319009", id);
+    EXPECT_EQ("0x319009", id);
 
     std::string ph;
     EXPECT_TRUE((item && item->GetString("ph", &ph)));
@@ -639,7 +644,7 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
     EXPECT_EQ(kThreadId, val);
     std::string id;
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ(kAsyncId, atoi(id.c_str()));
+    EXPECT_EQ(kAsyncIdStr, id);
   }
 
   EXPECT_FIND_("TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call");
@@ -651,7 +656,7 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
     EXPECT_EQ(kThreadId, val);
     std::string id;
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ(kAsyncId, atoi(id.c_str()));
+    EXPECT_EQ(kAsyncIdStr, id);
   }
 
   EXPECT_FIND_("TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
@@ -663,7 +668,7 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
     EXPECT_EQ(kThreadId, val);
     std::string id;
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ(kAsyncId + 1, atoi(id.c_str()));
+    EXPECT_EQ(kAsyncId2Str, id);
   }
 
   EXPECT_FIND_("TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call");
@@ -675,41 +680,63 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
     EXPECT_EQ(kThreadId, val);
     std::string id;
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ(kAsyncId + 1, atoi(id.c_str()));
+    EXPECT_EQ(kAsyncId2Str, id);
   }
 
   EXPECT_FIND_("tracked object 1");
   {
     std::string phase;
     std::string id;
+    std::string snapshot;
 
     EXPECT_TRUE((item && item->GetString("ph", &phase)));
     EXPECT_EQ("N", phase);
     EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ("42", id);
-    EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "tracked object 1",
-                                       item)));
-    EXPECT_TRUE((item && item->GetString("ph", &phase)));
+    EXPECT_EQ("0x42", id);
+
+    item = FindTraceEntry(trace_parsed, "tracked object 1", item);
+    EXPECT_TRUE(item);
+    EXPECT_TRUE(item && item->GetString("ph", &phase));
+    EXPECT_EQ("O", phase);
+    EXPECT_TRUE(item && item->GetString("id", &id));
+    EXPECT_EQ("0x42", id);
+    EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
+    EXPECT_EQ("hello", snapshot);
+
+    item = FindTraceEntry(trace_parsed, "tracked object 1", item);
+    EXPECT_TRUE(item);
+    EXPECT_TRUE(item && item->GetString("ph", &phase));
     EXPECT_EQ("D", phase);
-    EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ("42", id);
+    EXPECT_TRUE(item && item->GetString("id", &id));
+    EXPECT_EQ("0x42", id);
   }
 
   EXPECT_FIND_("tracked object 2");
   {
     std::string phase;
     std::string id;
+    std::string snapshot;
 
-    EXPECT_TRUE((item && item->GetString("ph", &phase)));
+    EXPECT_TRUE(item && item->GetString("ph", &phase));
     EXPECT_EQ("N", phase);
-    EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ("2128506", id);
-    EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "tracked object 2",
-                                       item)));
-    EXPECT_TRUE((item && item->GetString("ph", &phase)));
+    EXPECT_TRUE(item && item->GetString("id", &id));
+    EXPECT_EQ("0x2128506", id);
+
+    item = FindTraceEntry(trace_parsed, "tracked object 2", item);
+    EXPECT_TRUE(item);
+    EXPECT_TRUE(item && item->GetString("ph", &phase));
+    EXPECT_EQ("O", phase);
+    EXPECT_TRUE(item && item->GetString("id", &id));
+    EXPECT_EQ("0x2128506", id);
+    EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
+    EXPECT_EQ("world", snapshot);
+
+    item = FindTraceEntry(trace_parsed, "tracked object 2", item);
+    EXPECT_TRUE(item);
+    EXPECT_TRUE(item && item->GetString("ph", &phase));
     EXPECT_EQ("D", phase);
-    EXPECT_TRUE((item && item->GetString("id", &id)));
-    EXPECT_EQ("2128506", id);
+    EXPECT_TRUE(item && item->GetString("id", &id));
+    EXPECT_EQ("0x2128506", id);
   }
 }
 
@@ -1093,12 +1120,12 @@ TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
   EXPECT_TRUE(FindNamePhase("name1", "F"));
 
   std::string id_str;
-  StringAppendF(&id_str, "%llx", id);
+  StringAppendF(&id_str, "0x%llx", id);
 
   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "T", "id", id_str.c_str()));
   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
-  EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0"));
+  EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0x0"));
 
   // BEGIN events should not have id
   EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
diff --git a/base/test/trace_event_analyzer_unittest.cc b/base/test/trace_event_analyzer_unittest.cc
index 1e96bab..bb3e0fd 100644
--- a/base/test/trace_event_analyzer_unittest.cc
+++ b/base/test/trace_event_analyzer_unittest.cc
@@ -498,8 +498,8 @@ TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
   TraceEventVector found;
   analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
   ASSERT_EQ(2u, found.size());
-  EXPECT_STRCASEEQ("B", found[0]->id.c_str());
-  EXPECT_STRCASEEQ("C", found[1]->id.c_str());
+  EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
+  EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
 }
 
 // Test AssociateAsyncBeginEndEvents
@@ -531,13 +531,13 @@ TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
   analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
   ASSERT_EQ(3u, found.size());
 
-  EXPECT_STRCASEEQ("B", found[0]->id.c_str());
+  EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP, found[0]->other_event->phase);
   EXPECT_TRUE(found[0]->other_event->other_event);
   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
             found[0]->other_event->other_event->phase);
 
-  EXPECT_STRCASEEQ("C", found[1]->id.c_str());
+  EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP, found[1]->other_event->phase);
   EXPECT_TRUE(found[1]->other_event->other_event);
   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP,
@@ -550,7 +550,7 @@ TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
             found[1]->other_event->other_event->other_event->phase);
 
-  EXPECT_STRCASEEQ("A", found[2]->id.c_str());
+  EXPECT_STRCASEEQ("0xa", found[2]->id.c_str());
   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP, found[2]->other_event->phase);
 }