tp: parse begin and end async systrace events associated to tracks

This CL adds support for parsing 'T' and 'U' events introduced in
aosp/2037685

Bug: 221119585
Change-Id: I6831c5eb81f88306f4482f5f74860fb6058609a0

24 files changed, 145 insertions, 31 deletions

diff --git a/src/trace_processor/importers/systrace/systrace_parser.cc b/src/trace_processor/importers/systrace/systrace_parser.cc
index 7e9accddd..a8c585478 100644
--- a/src/trace_processor/importers/systrace/systrace_parser.cc
+++ b/src/trace_processor/importers/systrace/systrace_parser.cc
@@ -217,7 +217,9 @@ void SystraceParser::ParseSystracePoint(
       break;
     }
 
-    case 'N': {
+    case 'N':
+    case 'T':
+    case 'U': {
       StringId name_id = context_->storage->InternString(point.name);
       StringId track_name_id = context_->storage->InternString(point.str_value);
       UniquePid upid =
@@ -225,9 +227,21 @@ void SystraceParser::ParseSystracePoint(
       auto track_set_id =
           context_->async_track_set_tracker->InternProcessTrackSet(
               upid, track_name_id);
-      TrackId track_id =
-          context_->async_track_set_tracker->Scoped(track_set_id, ts, 0);
-      context_->slice_tracker->Scoped(ts, track_id, kNullStringId, name_id, 0);
+
+      if (point.phase == 'N') {
+        TrackId track_id =
+            context_->async_track_set_tracker->Scoped(track_set_id, ts, 0);
+        context_->slice_tracker->Scoped(ts, track_id, kNullStringId, name_id,
+                                        0);
+      } else if (point.phase == 'T') {
+        TrackId track_id = context_->async_track_set_tracker->Begin(
+            track_set_id, point.int_value);
+        context_->slice_tracker->Begin(ts, track_id, kNullStringId, name_id);
+      } else if (point.phase == 'U') {
+        TrackId track_id = context_->async_track_set_tracker->End(
+            track_set_id, point.int_value);
+        context_->slice_tracker->End(ts, track_id);
+      }
       break;
     }
 
diff --git a/src/trace_processor/importers/systrace/systrace_parser.h b/src/trace_processor/importers/systrace/systrace_parser.h
index c6e506a8a..af0f21f27 100644
--- a/src/trace_processor/importers/systrace/systrace_parser.h
+++ b/src/trace_processor/importers/systrace/systrace_parser.h
@@ -75,6 +75,22 @@ struct SystraceTracePoint {
                               std::move(track_name));
   }
 
+  static SystraceTracePoint T(uint32_t tgid,
+                              base::StringView track_name,
+                              base::StringView name,
+                              int64_t cookie) {
+    return SystraceTracePoint('T', tgid, std::move(name), cookie,
+                              std::move(track_name));
+  }
+
+  static SystraceTracePoint U(uint32_t tgid,
+                              base::StringView track_name,
+                              base::StringView name,
+                              int64_t cookie) {
+    return SystraceTracePoint('U', tgid, std::move(name), cookie,
+                              std::move(track_name));
+  }
+
   SystraceTracePoint(char p,
                      uint32_t tg,
                      base::StringView n,
@@ -82,18 +98,18 @@ struct SystraceTracePoint {
                      base::StringView s)
       : phase(p), tgid(tg), name(std::move(n)), int_value(v), str_value(s) {}
 
-  // Phase can be one of B, E, C, S, F.
+  // Phase can be one of B, E, C, S, F, I, N, T, U.
   char phase = '\0';
 
   uint32_t tgid = 0;
 
-  // For phase = 'B' and phase = 'C' only.
+  // For phase = B, C, S, F, N, U, T, U.
   base::StringView name;
 
-  // For phase = 'C' (counter value) and 'B', 'F' (async cookie).
+  // For phase = C (counter value) and B, S, F, N, T, U (async cookie).
   int64_t int_value = 0;
 
-  // For phase = 'N' (instant on track)
+  // For phase = N, T, U (track name)
   base::StringView str_value;
 
   // Visible for unittesting.
@@ -107,17 +123,19 @@ struct SystraceTracePoint {
 };
 
 // We have to handle trace_marker events of a few different types:
-// 1. some random text
-// 2. B|1636|pokeUserActivity
-// 3. E|1636
-// 4. C|1636|wq:monitor|0
-// 5. S|1636|frame_capture|123
-// 6. F|1636|frame_capture|456
+// 1.   some random text
+// 2.   B|1636|pokeUserActivity
+// 3.   E|1636
+// 4.   C|1636|wq:monitor|0
+// 5.   S|1636|frame_capture|123
+// 6.   F|1636|frame_capture|456
+// 7.   C|3209|TransfersBytesPendingOnDisk-value|0|Blob
+// 8.   I|4820|instant
+// 9.   N|1938|track_name|instant_name
+// 10.  T|1339|track_name|slice_name|789
+// 11.  U|6890|track_name|slice_name|135
 // Counters emitted by chromium can have a further "category group" appended
 // ("Blob" in the example below). We ignore the category group.
-// 7. C|3209|TransfersBytesPendingOnDisk-value|0|Blob
-// 8. I|4820|instant
-// 9. N|1938|track_name|instant_name
 inline SystraceParseResult ParseSystraceTracePoint(
     base::StringView str_untrimmed,
     SystraceTracePoint* out) {
@@ -219,6 +237,20 @@ inline SystraceParseResult ParseSystraceTracePoint(
       out->int_value = *maybe_value;
       return SystraceParseResult::kSuccess;
     }
+    case 'T':    // Begin of async slice on track.
+    case 'U': {  // End of async slice on track.
+      auto f2_track_name = read_next_field();
+      auto f3_name = read_next_field();
+      auto maybe_cookie = base::StringToInt64(read_next_field().ToStdString());
+      if (PERFETTO_UNLIKELY(!has_tgid || f2_track_name.empty() ||
+                            f3_name.empty() || !maybe_cookie)) {
+        return SystraceParseResult::kFailure;
+      }
+      out->name = f3_name;
+      out->str_value = f2_track_name;
+      out->int_value = *maybe_cookie;
+      return SystraceParseResult::kSuccess;
+    }
     default:
       if (str.find("trace_event_clock_sync:") == 0)
         return SystraceParseResult::kUnsupported;
diff --git a/src/trace_processor/importers/systrace/systrace_parser_unittest.cc b/src/trace_processor/importers/systrace/systrace_parser_unittest.cc
index be0d801ba..07431c6b5 100644
--- a/src/trace_processor/importers/systrace/systrace_parser_unittest.cc
+++ b/src/trace_processor/importers/systrace/systrace_parser_unittest.cc
@@ -108,6 +108,32 @@ TEST(SystraceParserTest, SystraceEvent) {
             Result::kUnsupported);
 }
 
+TEST(SystraceParserTest, AsyncTrackEvents) {
+  SystraceTracePoint result{};
+  ASSERT_EQ(ParseSystraceTracePoint("T", &result), Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("U", &result), Result::kFailure);
+
+  ASSERT_EQ(ParseSystraceTracePoint("T||test|test|", &result),
+            Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("T|123|test||", &result), Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("T|123||test|", &result), Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("T|123|track|event|", &result),
+            Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("T|123|track|event|456", &result),
+            Result::kSuccess);
+  EXPECT_EQ(result, SystraceTracePoint::T(123, "track", "event", 456));
+
+  ASSERT_EQ(ParseSystraceTracePoint("U||test|test|", &result),
+            Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("U|123|test||", &result), Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("U|123||test|", &result), Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("U|123|track|event|", &result),
+            Result::kFailure);
+  ASSERT_EQ(ParseSystraceTracePoint("U|123|track|event|456", &result),
+            Result::kSuccess);
+  EXPECT_EQ(result, SystraceTracePoint::U(123, "track", "event", 456));
+}
+
 }  // namespace
 }  // namespace systrace_utils
 }  // namespace trace_processor
diff --git a/test/trace_processor/parsing/android_async_slice.textproto b/test/trace_processor/atrace/android_async_slice.textproto
index 787d929f6..787d929f6 100644
--- a/test/trace_processor/parsing/android_async_slice.textproto
+++ b/test/trace_processor/atrace/android_async_slice.textproto
diff --git a/test/trace_processor/parsing/android_b2b_async_begin.textproto b/test/trace_processor/atrace/android_b2b_async_begin.textproto
index 121dfe193..121dfe193 100644
--- a/test/trace_processor/parsing/android_b2b_async_begin.textproto
+++ b/test/trace_processor/atrace/android_b2b_async_begin.textproto
diff --git a/test/trace_processor/parsing/android_b2b_async_begin_list_slices.out b/test/trace_processor/atrace/android_b2b_async_begin_list_slices.out
index a11b96c55..a11b96c55 100644
--- a/test/trace_processor/parsing/android_b2b_async_begin_list_slices.out
+++ b/test/trace_processor/atrace/android_b2b_async_begin_list_slices.out
diff --git a/test/trace_processor/atrace/async_track_atrace.py b/test/trace_processor/atrace/async_track_atrace.py
new file mode 100644
index 000000000..121f6d31f
--- /dev/null
+++ b/test/trace_processor/atrace/async_track_atrace.py
@@ -0,0 +1,37 @@
+#!/usr/bin/env python3
+# Copyright (C) 2022 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+from os import sys, path
+
+import synth_common
+
+trace = synth_common.create_trace()
+
+trace.add_packet()
+trace.add_process(pid=1, ppid=0, cmdline="p1")
+trace.add_process(pid=2, ppid=1, cmdline="p2")
+
+trace.add_thread(tid=1, tgid=1, cmdline='p1', name='p1')
+trace.add_thread(tid=2, tgid=2, cmdline='p2', name='p2')
+
+trace.add_ftrace_packet(cpu=0)
+trace.add_print(ts=50, tid=1, buf='T|1|track|ev|1024\n')
+trace.add_print(ts=55, tid=1, buf='T|1|track|ev|2048\n')
+trace.add_print(ts=60, tid=2, buf='T|2|track|ev|1024\n')
+trace.add_print(ts=65, tid=2, buf='U|2|track|ev|1024\n')
+trace.add_print(ts=70, tid=1, buf='U|1|track|ev|2048\n')
+trace.add_print(ts=75, tid=1, buf='U|1|track|ev|1024\n')
+
+sys.stdout.buffer.write(trace.trace.SerializeToString())
diff --git a/test/trace_processor/atrace/async_track_atrace_process_track_slices.out b/test/trace_processor/atrace/async_track_atrace_process_track_slices.out
new file mode 100644
index 000000000..3023fcf15
--- /dev/null
+++ b/test/trace_processor/atrace/async_track_atrace_process_track_slices.out
@@ -0,0 +1,4 @@
+"ts","dur","pid","slice_name","track_name"
+50,25,1,"ev","track"
+55,15,1,"ev","track"
+60,5,2,"ev","track"
diff --git a/test/trace_processor/parsing/bad_print.systrace b/test/trace_processor/atrace/bad_print.systrace
index cb1278024..cb1278024 100644
--- a/test/trace_processor/parsing/bad_print.systrace
+++ b/test/trace_processor/atrace/bad_print.systrace
diff --git a/test/trace_processor/parsing/bad_print.textproto b/test/trace_processor/atrace/bad_print.textproto
index 388946dec..388946dec 100644
--- a/test/trace_processor/parsing/bad_print.textproto
+++ b/test/trace_processor/atrace/bad_print.textproto
diff --git a/test/trace_processor/parsing/bad_print_systrace_list_slices.out b/test/trace_processor/atrace/bad_print_systrace_list_slices.out
index 6b081c875..6b081c875 100644
--- a/test/trace_processor/parsing/bad_print_systrace_list_slices.out
+++ b/test/trace_processor/atrace/bad_print_systrace_list_slices.out
diff --git a/test/trace_processor/parsing/bad_print_textproto_list_slices.out b/test/trace_processor/atrace/bad_print_textproto_list_slices.out
index 1f44a902a..1f44a902a 100644
--- a/test/trace_processor/parsing/bad_print_textproto_list_slices.out
+++ b/test/trace_processor/atrace/bad_print_textproto_list_slices.out
diff --git a/test/trace_processor/atrace/index b/test/trace_processor/atrace/index
new file mode 100644
index 000000000..32a8119dd
--- /dev/null
+++ b/test/trace_processor/atrace/index
@@ -0,0 +1,13 @@
+# Check error handling when parsing print events.
+bad_print.textproto ../common/list_slices.sql bad_print_textproto_list_slices.out
+bad_print.systrace ../common/list_slices.sql bad_print_systrace_list_slices.out
+instant_atrace.py instant_with_thread.sql instant_atrace_instant_with_thread.out
+instant_async_atrace.py instant_async.sql instant_async_atrace_instant_async.out
+
+# Match legacy Catapult behaviour when we see multiple S events b2b with the same cookie
+# name and upid.
+android_b2b_async_begin.textproto ../common/list_slices.sql android_b2b_async_begin_list_slices.out
+
+# Android userspace async slices
+android_async_slice.textproto ../common/process_track_slices.sql process_track_slices_android_async_slice.out
+async_track_atrace.py ../common/process_track_slices.sql async_track_atrace_process_track_slices.out
diff --git a/test/trace_processor/parsing/instant_async.sql b/test/trace_processor/atrace/instant_async.sql
index a02b2ba94..a02b2ba94 100644
--- a/test/trace_processor/parsing/instant_async.sql
+++ b/test/trace_processor/atrace/instant_async.sql
diff --git a/test/trace_processor/parsing/instant_async_atrace.py b/test/trace_processor/atrace/instant_async_atrace.py
index effdf8bf3..effdf8bf3 100644
--- a/test/trace_processor/parsing/instant_async_atrace.py
+++ b/test/trace_processor/atrace/instant_async_atrace.py
diff --git a/test/trace_processor/parsing/instant_async_atrace_instant_async.out b/test/trace_processor/atrace/instant_async_atrace_instant_async.out
index d95fe518b..d95fe518b 100644
--- a/test/trace_processor/parsing/instant_async_atrace_instant_async.out
+++ b/test/trace_processor/atrace/instant_async_atrace_instant_async.out
diff --git a/test/trace_processor/parsing/instant_atrace.py b/test/trace_processor/atrace/instant_atrace.py
index c7d6b628c..c7d6b628c 100644
--- a/test/trace_processor/parsing/instant_atrace.py
+++ b/test/trace_processor/atrace/instant_atrace.py
diff --git a/test/trace_processor/parsing/instant_atrace_instant_with_thread.out b/test/trace_processor/atrace/instant_atrace_instant_with_thread.out
index c1b730562..c1b730562 100644
--- a/test/trace_processor/parsing/instant_atrace_instant_with_thread.out
+++ b/test/trace_processor/atrace/instant_atrace_instant_with_thread.out
diff --git a/test/trace_processor/parsing/instant_with_thread.sql b/test/trace_processor/atrace/instant_with_thread.sql
index 2e39608cb..2e39608cb 100644
--- a/test/trace_processor/parsing/instant_with_thread.sql
+++ b/test/trace_processor/atrace/instant_with_thread.sql
diff --git a/test/trace_processor/parsing/process_track_slices_android_async_slice.out b/test/trace_processor/atrace/process_track_slices_android_async_slice.out
index a30a8f038..a30a8f038 100644
--- a/test/trace_processor/parsing/process_track_slices_android_async_slice.out
+++ b/test/trace_processor/atrace/process_track_slices_android_async_slice.out
diff --git a/test/trace_processor/parsing/list_slices.sql b/test/trace_processor/common/list_slices.sql
index 211ae893a..55b0d7256 100644
--- a/test/trace_processor/parsing/list_slices.sql
+++ b/test/trace_processor/common/list_slices.sql
@@ -1,2 +1,2 @@
 SELECT ts, dur, name
-FROM slice
\ No newline at end of file
+FROM slice
diff --git a/test/trace_processor/parsing/process_track_slices.sql b/test/trace_processor/common/process_track_slices.sql
index 1b9151dca..1b9151dca 100644
--- a/test/trace_processor/parsing/process_track_slices.sql
+++ b/test/trace_processor/common/process_track_slices.sql
diff --git a/test/trace_processor/include_index b/test/trace_processor/include_index
index 593e33892..29a7b414e 100644
--- a/test/trace_processor/include_index
+++ b/test/trace_processor/include_index
@@ -1,3 +1,4 @@
+atrace/index
 camera/index
 chrome/index
 cros/index
diff --git a/test/trace_processor/parsing/index b/test/trace_processor/parsing/index
index 4913f0b19..9952dea32 100644
--- a/test/trace_processor/parsing/index
+++ b/test/trace_processor/parsing/index
@@ -56,9 +56,6 @@ ion_stat.textproto ion_stat.sql ion_stat.out
 # Mm Event
 ../../data/mm_event.pb mm_event.sql mm_event.out
 
-# Android userspace async slices
-android_async_slice.textproto process_track_slices.sql process_track_slices_android_async_slice.out
-
 # Check the systrace conversion code in the raw table.
 # Print events
 ../../data/lmk_userspace.pb print_systrace.sql print_systrace_lmk_userspace.out
@@ -75,16 +72,6 @@ cgroup_attach_task_post_s.textproto print_systrace.sql cgroup_attach_task_post_s
 ../../data/systrace.html systrace_html.sql systrace_html.out
 ../../data/trailing_empty.systrace sched_smoke.sql sched_smoke_trailing_empty.out
 
-# Check error handling when parsing print events.
-bad_print.textproto list_slices.sql bad_print_textproto_list_slices.out
-bad_print.systrace list_slices.sql bad_print_systrace_list_slices.out
-instant_atrace.py instant_with_thread.sql instant_atrace_instant_with_thread.out
-instant_async_atrace.py instant_async.sql instant_async_atrace_instant_async.out
-
-# Match legacy Catapult behaviour when we see multiple S events b2b with the same cookie
-# name and upid.
-android_b2b_async_begin.textproto list_slices.sql android_b2b_async_begin_list_slices.out
-
 # LMK handling
 kernel_lmk.py lmk.sql lmk_kernel_lmk.out
 ../../data/lmk_userspace.pb lmk.sql lmk_userspace_lmk.out