Plot async steps in about:tracing.

BUG=None
TEST=base_unittests,timeline_test.html,trace_event_importer_test.html


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

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

3 files changed, 36 insertions, 41 deletions

diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 349619c..00e0208 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -388,6 +388,12 @@
 //   match. |id| must either be a pointer or an integer value up to 64 bits. If
 //   it's a pointer, the bits will be xored with a hash of the process ID so
 //   that the same pointer on two different processes will not collide.
+// An asynchronous operation can consist of multiple phases. The first phase is
+// defined by the ASYNC_BEGIN calls. Additional phases can be defined using the
+// ASYNC_STEP_BEGIN macros. When the operation completes, call ASYNC_END.
+// An async operation can span threads and processes, but all events in that
+// operation must use the same |name| and |id|. Each event can have its own
+// args.
 #define TRACE_EVENT_ASYNC_BEGIN0(category, name, id) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, \
         category, name, id, TRACE_EVENT_FLAG_NONE)
@@ -412,31 +418,27 @@
         category, name, id, TRACE_EVENT_FLAG_COPY, \
         arg1_name, arg1_val, arg2_name, arg2_val)
 
-// Records a single ASYNC_STEP event for "name" immediately. If the category
-// is not enabled, then this does nothing.
-#define TRACE_EVENT_ASYNC_STEP0(category, name, id) \
+// Records a single ASYNC_STEP event for |step| immediately. If the category
+// is not enabled, then this does nothing. The |name| and |id| must match the
+// ASYNC_BEGIN event above. The |step| param identifies this step within the
+// async event. This should be called at the beginning of the next phase of an
+// asynchronous operation.
+#define TRACE_EVENT_ASYNC_BEGIN_STEP0(category, name, id, step) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, \
-        category, name, id, TRACE_EVENT_FLAG_NONE)
-#define TRACE_EVENT_ASYNC_STEP1(category, name, id, arg1_name, arg1_val) \
+        category, name, id, TRACE_EVENT_FLAG_NONE, "step", step)
+#define TRACE_EVENT_ASYNC_BEGIN_STEP1(category, name, id, step, \
+                                      arg1_name, arg1_val) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, \
-        category, name, id, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val)
-#define TRACE_EVENT_ASYNC_STEP2(category, name, id, arg1_name, arg1_val, \
-        arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, \
-        category, name, id, TRACE_EVENT_FLAG_NONE, \
-        arg1_name, arg1_val, arg2_name, arg2_val)
-#define TRACE_EVENT_COPY_ASYNC_STEP0(category, name, id) \
+        category, name, id, TRACE_EVENT_FLAG_NONE, "step", step, \
+        arg1_name, arg1_val)
+#define TRACE_EVENT_COPY_ASYNC_BEGIN_STEP0(category, name, id, step) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, \
-        category, name, id, TRACE_EVENT_FLAG_COPY)
-#define TRACE_EVENT_COPY_ASYNC_STEP1(category, name, id, arg1_name, arg1_val) \
+        category, name, id, TRACE_EVENT_FLAG_COPY, "step", step)
+#define TRACE_EVENT_COPY_ASYNC_BEGIN_STEP1(category, name, id, step, \
+        arg1_name, arg1_val) \
     INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, \
-        category, name, id, TRACE_EVENT_FLAG_COPY, \
+        category, name, id, TRACE_EVENT_FLAG_COPY, "step", step, \
         arg1_name, arg1_val)
-#define TRACE_EVENT_COPY_ASYNC_STEP2(category, name, id, arg1_name, arg1_val, \
-        arg2_name, arg2_val) \
-    INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, \
-        category, name, id, TRACE_EVENT_FLAG_COPY, \
-        arg1_name, arg1_val, arg2_name, arg2_val)
 
 // Records a single ASYNC_END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index 94be430..f9a8b7a 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -330,12 +330,10 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
                              "name1", "value1",
                              "name2", "value2");
 
-    TRACE_EVENT_ASYNC_STEP0("all", "TRACE_EVENT_ASYNC_STEP0 call", 5);
-    TRACE_EVENT_ASYNC_STEP1("all", "TRACE_EVENT_ASYNC_STEP1 call", 5,
-                            "name1", "value1");
-    TRACE_EVENT_ASYNC_STEP2("all", "TRACE_EVENT_ASYNC_STEP2 call", 5,
-                            "name1", "value1",
-                            "name2", "value2");
+    TRACE_EVENT_ASYNC_BEGIN_STEP0("all", "TRACE_EVENT_ASYNC_BEGIN_STEP0 call",
+                                  5, "step1");
+    TRACE_EVENT_ASYNC_BEGIN_STEP1("all", "TRACE_EVENT_ASYNC_BEGIN_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,
@@ -463,21 +461,16 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
   EXPECT_SUB_FIND_("name2");
   EXPECT_SUB_FIND_("value2");
 
-  EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP0 call");
+  EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN_STEP0 call");
   EXPECT_SUB_FIND_("id");
   EXPECT_SUB_FIND_("5");
-  EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP1 call");
+  EXPECT_SUB_FIND_("step1");
+  EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN_STEP1 call");
   EXPECT_SUB_FIND_("id");
   EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_("step2");
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
-  EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP2 call");
-  EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
-  EXPECT_SUB_FIND_("name1");
-  EXPECT_SUB_FIND_("value1");
-  EXPECT_SUB_FIND_("name2");
-  EXPECT_SUB_FIND_("value2");
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
   EXPECT_SUB_FIND_("id");
@@ -947,7 +940,7 @@ TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
 
   unsigned long long id = 0xfeedbeeffeedbeefull;
   TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", id);
-  TRACE_EVENT_ASYNC_STEP0( "cat", "name1", id);
+  TRACE_EVENT_ASYNC_BEGIN_STEP0( "cat", "name1", id, "step1");
   TRACE_EVENT_ASYNC_END0("cat", "name1", id);
   TRACE_EVENT_BEGIN0( "cat", "name2");
   TRACE_EVENT_ASYNC_BEGIN0( "cat", "name3", 0);
diff --git a/base/test/trace_event_analyzer_unittest.cc b/base/test/trace_event_analyzer_unittest.cc
index 55309db..dd1ce4d 100644
--- a/base/test/trace_event_analyzer_unittest.cc
+++ b/base/test/trace_event_analyzer_unittest.cc
@@ -503,17 +503,17 @@ TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
 
   BeginTracing();
   {
-    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xA);
+    TRACE_EVENT_ASYNC_BEGIN_STEP0("c", "n", 0xA, "s1");
     TRACE_EVENT_ASYNC_END0("c", "n", 0xA);
     TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB);
     TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC);
-    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xB);
-    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xC);
-    TRACE_EVENT_ASYNC_STEP1("c", "n", 0xC, "a", 1);
+    TRACE_EVENT_ASYNC_BEGIN_STEP0("c", "n", 0xB, "s1");
+    TRACE_EVENT_ASYNC_BEGIN_STEP0("c", "n", 0xC, "s1");
+    TRACE_EVENT_ASYNC_BEGIN_STEP1("c", "n", 0xC, "s2", "a", 1);
     TRACE_EVENT_ASYNC_END0("c", "n", 0xB);
     TRACE_EVENT_ASYNC_END0("c", "n", 0xC);
     TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA);
-    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xA);
+    TRACE_EVENT_ASYNC_BEGIN_STEP0("c", "n", 0xA, "s2");
   }
   EndTracing();