Adding raw tracing to trace framework.

base/debug/trace_event_unittest.cc

 // Copyright (c) 2012 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.
 
 #include "base/debug/trace_event_unittest.h"
 
+#include <cstdlib>
+
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/trace_event.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/memory/singleton.h"
 #include "base/process_util.h"
 #include "base/stringprintf.h"
@@ skipping 15 matching lines @@
   IS_EQUAL,
   IS_NOT_EQUAL,
 };
 
 struct JsonKeyValue {
   const char* key;
   const char* value;
   CompareOp op;
 };
 
+static int kThreadId = 42;
+static int kAsyncId = 5;
+static const char kAsyncIdStr[] = "5";
+
 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(
       const scoped_refptr<base::RefCountedString>& events_str);
   void OnTraceNotification(int notification) {
     if (notification & TraceLog::EVENT_WATCH_NOTIFICATION)
       ++event_watch_notification_;
@@ skipping 278 matching lines @@
     TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call",
                        "name1", "value1",
                        "name2", "value2");
 
     TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call");
     TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1");
     TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call",
                      "name1", "value1",
                      "name2", "value2");
 
-    TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", 5);
-    TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", 5,
+    TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", kAsyncId);
+    TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", kAsyncId,
                              "name1", "value1");
-    TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", 5,
+    TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", kAsyncId,
                              "name1", "value1",
                              "name2", "value2");
 
     TRACE_EVENT_ASYNC_STEP0("all", "TRACE_EVENT_ASYNC_STEP0 call",
                                   5, "step1");
     TRACE_EVENT_ASYNC_STEP1("all", "TRACE_EVENT_ASYNC_STEP1 call",
                                   5, "step2", "name1", "value1");
 
-    TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", 5);
-    TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", 5,
+    TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", kAsyncId);
+    TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", kAsyncId,
                            "name1", "value1");
-    TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", 5,
+    TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", kAsyncId,
                            "name1", "value1",
                            "name2", "value2");
 
-    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", 5, NULL);
-    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", 5, "value");
-    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", 5, NULL);
-    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", 5, "value");
-    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", 5, NULL);
-    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", 5, "value");
+    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", kAsyncId, NULL);
+    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", kAsyncId, "value");
+    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", kAsyncId, NULL);
+    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", kAsyncId, "value");
+    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", kAsyncId, NULL);
+    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", kAsyncId, "value");
 
     TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
     TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
                    "a", 30000,
                    "b", 1415);
 
     TRACE_COUNTER_ID1("all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
     TRACE_COUNTER_ID2("all", "TRACE_COUNTER_ID2 call", 0x319009,
                       "a", 30000, "b", 1415);
+
+    TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId, kThreadId, 12345);
+    TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId, kThreadId, 23456);
+
+    TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId + 1, kThreadId, 34567);
+    TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId + 1, kThreadId, 45678);
+
   } // Scope close causes TRACE_EVENT0 etc to send their END events.
 
   if (task_complete_event)
     task_complete_event->Signal();
 }
 
 void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
   const DictionaryValue* item = NULL;
 
 #define EXPECT_FIND_(string) \
@@ skipping 60 matching lines @@
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_FIND_("TRACE_EVENT_END2 call");
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_SUB_FIND_("name2");
   EXPECT_SUB_FIND_("value2");
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_SUB_FIND_("name2");
   EXPECT_SUB_FIND_("value2");
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("step1");
   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("step2");
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_SUB_FIND_("name2");
   EXPECT_SUB_FIND_("value2");
 
   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("NULL");
   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("value");
   EXPECT_FIND_("TRACE_EVENT_END_ETW0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("NULL");
   EXPECT_FIND_("TRACE_EVENT_END_ETW1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("value");
   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("NULL");
   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("value");
 
   EXPECT_FIND_("TRACE_COUNTER1 call");
   {
     std::string ph;
     EXPECT_TRUE((item && item->GetString("ph", &ph)));
     EXPECT_EQ("C", ph);
 
     int value;
@@ skipping 40 matching lines @@
     EXPECT_TRUE((item && item->GetString("ph", &ph)));
     EXPECT_EQ("C", ph);
 
     int value;
     EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
     EXPECT_EQ(30000, value);
 
     EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
     EXPECT_EQ(1415, value);
   }
+
+  EXPECT_FIND_("TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(12345, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId, atoi(id.c_str()));
+  }
+
+  EXPECT_FIND_("TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(23456, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId, atoi(id.c_str()));
+  }
+
+  EXPECT_FIND_("TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(34567, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId + 1, atoi(id.c_str()));
+  }
+
+  EXPECT_FIND_("TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(45678, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId + 1, atoi(id.c_str()));
+  }
 }
 
 void TraceManyInstantEvents(int thread_id, int num_events,
                             WaitableEvent* task_complete_event) {
   for (int i = 0; i < num_events; i++) {
     TRACE_EVENT_INSTANT2("all", "multi thread event",
                          "thread", thread_id,
                          "event", i);
   }
 
@@ skipping 811 matching lines @@
   trace_log->SetEnabled(std::string("moo"));
   EXPECT_TRUE(*trace_log->GetCategoryEnabled("baz"));
   EXPECT_TRUE(*trace_log->GetCategoryEnabled("moo"));
   EXPECT_TRUE(*trace_log->GetCategoryEnabled("foo"));
   trace_log->SetDisabled();
   trace_log->SetDisabled();
 }
 
 }  // namespace debug
 }  // namespace base