arc: Support asyncronous trace events for system trace.

This is required for input tracing once some input traces are
asynchronous.

TEST=Locally in context of other CLs + unit test
BUG=b/132709527

Change-Id: I9c35c27433ba1cce838ce30a6a6e2ebae05d194a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1642490Reviewed-by: Xiyuan Xia <xiyuan@chromium.org>
Commit-Queue: Yury Khmel <khmel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#666041}

chrome/browser/chromeos/arc/tracing/arc_tracing_model.cc

@@ -99,6 +99,9 @@ struct GraphicsEventsContext {
   ArcTracingModel::TracingEvents converted_events;
   std::map<uint32_t, std::vector<ArcTracingEvent*>>
       per_thread_pending_events_stack;
+
+  std::map<std::pair<char, std::string>, std::unique_ptr<ArcTracingEvent>>
+      pending_asynchronous_events;
 };
 
 bool HandleGraphicsEvent(GraphicsEventsContext* context,
@@ -158,6 +161,41 @@ bool HandleGraphicsEvent(GraphicsEventsContext* context,
       completed_event->SetPhase(TRACE_EVENT_PHASE_COMPLETE);
       completed_event->SetDuration(timestamp - completed_event->GetTimestamp());
     } break;
+    case TRACE_EVENT_PHASE_ASYNC_BEGIN:
+    case TRACE_EVENT_PHASE_ASYNC_END: {
+      const size_t name_pos = ParseUint32(line, event_position + 2, '|', &pid);
+      if (name_pos == std::string::npos) {
+        LOG(ERROR) << "Cannot parse pid of trace event: " << line;
+        return false;
+      }
+      const size_t id_pos = line.find('|', name_pos + 2);
+      if (id_pos == std::string::npos) {
+        LOG(ERROR) << "Cannot parse name|id of trace event: " << line;
+        return false;
+      }
+      const std::string name = line.substr(name_pos + 1, id_pos - name_pos - 1);
+      const std::string id = line.substr(id_pos + 1);
+      std::unique_ptr<ArcTracingEvent> event =
+          std::make_unique<ArcTracingEvent>(base::DictionaryValue());
+      event->SetPhase(phase);
+      event->SetPid(pid);
+      event->SetTid(tid);
+      event->SetTimestamp(timestamp);
+      event->SetCategory(kAndroidCategory);
+      event->SetName(name);
+      // Id here is weak and theoretically can be replicated in another
+      // processes or for different event names.
+      const std::string full_id = line.substr(event_position + 2);
+      event->SetId(id);
+      if (context->pending_asynchronous_events.find({phase, full_id}) !=
+          context->pending_asynchronous_events.end()) {
+        LOG(ERROR) << "Found duplicated asynchronous event " << line;
+        // That could be the real case from Android framework, for example
+        // animator:opacity trace. Ignore these duplicate events.
+        return true;
+      }
+      context->pending_asynchronous_events[{phase, full_id}] = std::move(event);
+    } break;
     default:
       LOG(ERROR) << "Unsupported type of trace event: " << line;
       return false;
@@ -280,6 +318,15 @@ bool HandleGpuFreq(ValueEvents* value_events,
   return true;
 }
 
+bool SortByTimestampPred(const std::unique_ptr<ArcTracingEvent>& lhs,
+                         const std::unique_ptr<ArcTracingEvent>& rhs) {
+  const uint64_t lhs_timestamp = lhs->GetTimestamp();
+  const uint64_t rhs_timestamp = rhs->GetTimestamp();
+  if (lhs_timestamp != rhs_timestamp)
+    return lhs_timestamp < rhs_timestamp;
+  return lhs->GetDuration() > rhs->GetDuration();
+}
+
 }  // namespace
 
 ArcTracingModel::ArcTracingModel() = default;
@@ -325,6 +372,11 @@ bool ArcTracingModel::Build(const std::string& data) {
     return false;
   }
 
+  for (auto& group_events : group_events_) {
+    std::sort(group_events.second.begin(), group_events.second.end(),
+              SortByTimestampPred);
+  }
+
   return true;
 }
 
@@ -362,6 +414,17 @@ ArcTracingModel::TracingEventPtrs ArcTracingModel::Select(
   return collector;
 }
 
+ArcTracingModel::TracingEventPtrs ArcTracingModel::GetGroupEvents(
+    const std::string& id) const {
+  TracingEventPtrs result;
+  const auto& it = group_events_.find(id);
+  if (it == group_events_.end())
+    return result;
+  for (const auto& group_event : it->second)
+    result.emplace_back(group_event.get());
+  return result;
+}
+
 bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
   std::vector<std::unique_ptr<ArcTracingEvent>> parsed_events;
   for (auto& it : events->GetList()) {
@@ -400,14 +463,7 @@ bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
 
   // Events may come by closure that means event started earlier as a root event
   // for others may appear after children. Sort by ts time.
-  std::sort(parsed_events.begin(), parsed_events.end(),
-            [](const auto& lhs, const auto& rhs) {
-              const uint64_t lhs_timestamp = lhs->GetTimestamp();
-              const uint64_t rhs_timestamp = rhs->GetTimestamp();
-              if (lhs_timestamp != rhs_timestamp)
-                return lhs_timestamp < rhs->GetTimestamp();
-              return lhs->GetDuration() > rhs->GetDuration();
-            });
+  std::sort(parsed_events.begin(), parsed_events.end(), SortByTimestampPred);
 
   for (auto& event : parsed_events) {
     switch (event->GetPhase()) {
@@ -541,6 +597,12 @@ bool ArcTracingModel::ConvertSysTraces(const std::string& sys_traces) {
     }
   }
 
+  for (auto& asyncronous_event :
+       graphics_events_context.pending_asynchronous_events) {
+    group_events_[asyncronous_event.second->GetId()].emplace_back(
+        std::move(asyncronous_event.second));
+  }
+
   // Close all pending tracing event, assuming last event is 0 duration.
   for (auto& pending_events :
        graphics_events_context.per_thread_pending_events_stack) {

chrome/browser/chromeos/arc/tracing/arc_tracing_model.h

@@ -54,6 +54,9 @@ class ArcTracingModel {
   TracingEventPtrs Select(const ArcTracingEvent* event,
                           const std::string query) const;
 
+  // Gets group of asynchronous events for |id|.
+  TracingEventPtrs GetGroupEvents(const std::string& id) const;
+
   // Dumps this model to |stream|.
   void Dump(std::ostream& stream) const;
 

chrome/browser/chromeos/arc/tracing/arc_tracing_model_unittest.cc

@@ -11,6 +11,7 @@
 #include "base/json/json_writer.h"
 #include "base/macros.h"
 #include "base/path_service.h"
+#include "base/trace_event/common/trace_event_common.h"
 #include "chrome/browser/chromeos/arc/tracing/arc_tracing_event.h"
 #include "chrome/browser/chromeos/arc/tracing/arc_tracing_event_matcher.h"
 #include "chrome/browser/chromeos/arc/tracing/arc_tracing_graphics_model.h"
@@ -562,4 +563,43 @@ TEST_F(ArcTracingModelTest, EventsContainerTrim) {
             events.buffer_events()[0][0].type);
 }
 
+TEST_F(ArcTracingModelTest, AsynchronousSystemEvents) {
+  base::FilePath base_path;
+  base::PathService::Get(chrome::DIR_TEST_DATA, &base_path);
+  const base::FilePath tracing_path = base_path.Append("arc_graphics_tracing")
+                                          .Append("trace_async_events.json");
+  std::string tracing_data;
+  base::ReadFileToString(tracing_path, &tracing_data);
+  DCHECK(!tracing_data.empty());
+
+  ArcTracingModel model;
+  ASSERT_TRUE(model.Build(tracing_data));
+
+  const ArcTracingModel::TracingEventPtrs group1 = model.GetGroupEvents("1");
+  const ArcTracingModel::TracingEventPtrs group2 = model.GetGroupEvents("2");
+
+  constexpr char kAsync1[] = "async1";
+  constexpr char kAsync2[] = "async2";
+
+  ASSERT_EQ(2U, group1.size());
+  EXPECT_EQ(kAsync1, group1[0]->GetName());
+  EXPECT_EQ(kAsync1, group1[1]->GetName());
+  EXPECT_EQ("1", group1[0]->GetId());
+  EXPECT_EQ(group1[0]->GetId(), group1[1]->GetId());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_BEGIN, group1[0]->GetPhase());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END, group1[1]->GetPhase());
+  EXPECT_EQ(1100000UL, group1[0]->GetTimestamp());
+  EXPECT_EQ(1300000UL, group1[1]->GetTimestamp());
+
+  ASSERT_EQ(2U, group2.size());
+  EXPECT_EQ(kAsync2, group2[0]->GetName());
+  EXPECT_EQ(kAsync2, group2[1]->GetName());
+  EXPECT_EQ("2", group2[0]->GetId());
+  EXPECT_EQ(group2[0]->GetId(), group2[1]->GetId());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_BEGIN, group2[0]->GetPhase());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END, group2[1]->GetPhase());
+  EXPECT_EQ(1200000UL, group2[0]->GetTimestamp());
+  EXPECT_EQ(1400000UL, group2[1]->GetTimestamp());
+}
+
 }  // namespace arc

chrome/test/data/arc_graphics_tracing/trace_async_events.json

+{
+  "traceEvents":[],
+  "systemTraceEvents":"            app1-14141 [001] ...1     1.100000: tracing_mark_write: S|1141|async1|1\n            app2-14142 [001] ...1     1.200000: tracing_mark_write: S|1142|async2|2\n            app1-14141 [001] ...1     1.300000: tracing_mark_write: F|1141|async1|1\n            app2-14142 [001] ...1     1.400000: tracing_mark_write: F|1142|async2|2\n"
+}
+