arc: Restore functionality of graphics tracing tools.

Tracing was changed and no longer deliver events in right order. Parent
event is closed after children event and this is the order tracing event
appear. This CL pre-sorts events based on timestamp and duration to make
sure parent event goes first. This additionally fixes crashes in error
logging and removes bottleneck in building common tracing model.

TEST=Manually + unit test. Observed that common model is built in less
than second, compared with ~ min (debug unit test) with old approach.
BUG=b:122555793

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

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

@@ -60,7 +60,7 @@ std::string GetStringFromDictionary(const base::DictionaryValue* dictionary,
 
 }  // namespace
 
-ArcTracingEvent::ArcTracingEvent(std::unique_ptr<base::Value> dictionary)
+ArcTracingEvent::ArcTracingEvent(base::Value dictionary)
     : dictionary_(std::move(dictionary)) {}
 
 ArcTracingEvent::~ArcTracingEvent() = default;
@@ -71,7 +71,7 @@ int ArcTracingEvent::GetPid() const {
 }
 
 void ArcTracingEvent::SetPid(int pid) {
-  dictionary_->SetKey(kKeyPid, base::Value(pid));
+  dictionary_.SetKey(kKeyPid, base::Value(pid));
 }
 
 int ArcTracingEvent::GetTid() const {
@@ -80,7 +80,7 @@ int ArcTracingEvent::GetTid() const {
 }
 
 void ArcTracingEvent::SetTid(int tid) {
-  dictionary_->SetKey(kKeyTid, base::Value(tid));
+  dictionary_.SetKey(kKeyTid, base::Value(tid));
 }
 
 std::string ArcTracingEvent::GetId() const {
@@ -89,7 +89,7 @@ std::string ArcTracingEvent::GetId() const {
 }
 
 void ArcTracingEvent::SetId(const std::string& id) {
-  dictionary_->SetKey(kKeyId, base::Value(id));
+  dictionary_.SetKey(kKeyId, base::Value(id));
 }
 
 std::string ArcTracingEvent::GetCategory() const {
@@ -98,7 +98,7 @@ std::string ArcTracingEvent::GetCategory() const {
 }
 
 void ArcTracingEvent::SetCategory(const std::string& category) {
-  dictionary_->SetKey(kKeyCategory, base::Value(category));
+  dictionary_.SetKey(kKeyCategory, base::Value(category));
 }
 
 std::string ArcTracingEvent::GetName() const {
@@ -107,7 +107,7 @@ std::string ArcTracingEvent::GetName() const {
 }
 
 void ArcTracingEvent::SetName(const std::string& name) {
-  dictionary_->SetKey(kKeyName, base::Value(name));
+  dictionary_.SetKey(kKeyName, base::Value(name));
 }
 
 char ArcTracingEvent::GetPhase() const {
@@ -117,7 +117,7 @@ char ArcTracingEvent::GetPhase() const {
 }
 
 void ArcTracingEvent::SetPhase(char phase) {
-  dictionary_->SetKey(kKeyPhase, base::Value(std::string() + phase));
+  dictionary_.SetKey(kKeyPhase, base::Value(std::string() + phase));
 }
 
 int64_t ArcTracingEvent::GetTimestamp() const {
@@ -126,7 +126,7 @@ int64_t ArcTracingEvent::GetTimestamp() const {
 }
 
 void ArcTracingEvent::SetTimestamp(double timestamp) {
-  dictionary_->SetKey(kKeyTimestamp, base::Value(timestamp));
+  dictionary_.SetKey(kKeyTimestamp, base::Value(timestamp));
 }
 
 int64_t ArcTracingEvent::GetDuration() const {
@@ -135,7 +135,7 @@ int64_t ArcTracingEvent::GetDuration() const {
 }
 
 void ArcTracingEvent::SetDuration(double duration) {
-  dictionary_->SetKey(kKeyDuration, base::Value(duration));
+  dictionary_.SetKey(kKeyDuration, base::Value(duration));
 }
 
 int64_t ArcTracingEvent::GetEndTimestamp() const {
@@ -144,13 +144,13 @@ int64_t ArcTracingEvent::GetEndTimestamp() const {
 
 const base::DictionaryValue* ArcTracingEvent::GetDictionary() const {
   const base::DictionaryValue* dictionary = nullptr;
-  dictionary_->GetAsDictionary(&dictionary);
+  dictionary_.GetAsDictionary(&dictionary);
   return dictionary;
 }
 
 const base::DictionaryValue* ArcTracingEvent::GetArgs() const {
   const base::Value* value =
-      dictionary_->FindKeyOfType(kKeyArguments, base::Value::Type::DICTIONARY);
+      dictionary_.FindKeyOfType(kKeyArguments, base::Value::Type::DICTIONARY);
   if (!value)
     return nullptr;
   const base::DictionaryValue* args = nullptr;

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

@@ -29,7 +29,7 @@ class ArcTracingEvent {
     kOverlap,  // event overlaps with compared event.
   };
 
-  explicit ArcTracingEvent(std::unique_ptr<base::Value> dictionary);
+  explicit ArcTracingEvent(base::Value dictionary);
   ~ArcTracingEvent();
 
   // Gets process id of the event. Returns 0 if not set.
@@ -117,7 +117,7 @@ class ArcTracingEvent {
 
  private:
   std::vector<std::unique_ptr<ArcTracingEvent>> children_;
-  std::unique_ptr<base::Value> dictionary_;
+  base::Value dictionary_;
 
   DISALLOW_COPY_AND_ASSIGN(ArcTracingEvent);
 };

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

@@ -124,7 +124,7 @@ bool ArcTracingModel::Build(const std::string& data) {
   }
 
   if (!ProcessEvent(events)) {
-    LOG(ERROR) << "No trace events";
+    LOG(ERROR) << "Failed to process events";
     return false;
   }
 
@@ -166,12 +166,10 @@ ArcTracingModel::TracingEventPtrs ArcTracingModel::Select(
 }
 
 bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
-  base::ListValue::iterator it = events->begin();
-  while (it != events->end()) {
-    std::unique_ptr<base::Value> event_data;
-    // Take ownership.
-    it = events->Erase(it, &event_data);
-    if (!event_data->is_dict()) {
+  std::vector<std::unique_ptr<ArcTracingEvent>> parsed_events;
+  for (auto& it : events->GetList()) {
+    base::Value event_data = std::move(it);
+    if (!event_data.is_dict()) {
       LOG(ERROR) << "Event is not a dictionary";
       return false;
     }
@@ -200,6 +198,21 @@ bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
       return false;
     }
 
+    parsed_events.emplace_back(std::move(event));
+  }
+
+  // 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 int64_t lhs_timestamp = lhs->GetTimestamp();
+              const int64_t rhs_timestamp = rhs->GetTimestamp();
+              if (lhs_timestamp != rhs_timestamp)
+                return lhs_timestamp < rhs->GetTimestamp();
+              return lhs->GetDuration() > rhs->GetDuration();
+            });
+
+  for (auto& event : parsed_events) {
     switch (event->GetPhase()) {
       case TRACE_EVENT_PHASE_METADATA:
         metadata_events_.push_back(std::move(event));
@@ -212,7 +225,7 @@ bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
       case TRACE_EVENT_PHASE_COMPLETE:
       case TRACE_EVENT_PHASE_COUNTER:
         if (!AddToThread(std::move(event))) {
-          LOG(ERROR) << "Cannot add event to threads " << event->ToString();
+          LOG(ERROR) << "Cannot add event to threads";
           return false;
         }
         break;
@@ -222,16 +235,6 @@ bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
     }
   }
 
-  // Sort group events based on timestamp. They are asynchronous and may come in
-  // random order.
-  for (auto& gr : group_events_) {
-    std::sort(gr.second.begin(), gr.second.end(),
-              [](std::unique_ptr<ArcTracingEvent>& a,
-                 std::unique_ptr<ArcTracingEvent>& b) {
-                return a->GetTimestamp() < b->GetTimestamp();
-              });
-  }
-
   return true;
 }
 
@@ -324,8 +327,7 @@ bool ArcTracingModel::ConvertSysTraces(const std::string& sys_traces) {
         }
         const std::string name = line.substr(name_pos + 1);
         std::unique_ptr<ArcTracingEvent> event =
-            std::make_unique<ArcTracingEvent>(
-                std::make_unique<base::DictionaryValue>());
+            std::make_unique<ArcTracingEvent>(base::DictionaryValue());
         event->SetPid(pid);
         event->SetTid(tid);
         event->SetTimestamp(timestamp);
@@ -373,8 +375,7 @@ bool ArcTracingModel::ConvertSysTraces(const std::string& sys_traces) {
   // Now put events to the thread models.
   for (auto& converted_event : converted_events) {
     if (!AddToThread(std::move(converted_event))) {
-      LOG(ERROR) << "Cannot add systrace event to threads "
-                 << converted_event->ToString();
+      LOG(ERROR) << "Cannot add systrace event to threads";
       return false;
     }
   }
@@ -390,7 +391,7 @@ bool ArcTracingModel::AddToThread(std::unique_ptr<ArcTracingEvent> event) {
                                   ArcTracingEvent::Position::kAfter) {
     // First event for the thread or event is after already existing last root
     // event. Add as a new root.
-    thread_roots.push_back(std::move(event));
+    thread_roots.emplace_back(std::move(event));
     return true;
   }
 

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

@@ -202,7 +202,7 @@ TEST_F(ArcTracingModelTest, TopLevel) {
 }
 
 TEST_F(ArcTracingModelTest, Event) {
-  const ArcTracingEvent event(base::JSONReader::ReadDeprecated(kTestEvent));
+  const ArcTracingEvent event(base::JSONReader::Read(kTestEvent).value());
 
   EXPECT_EQ(4640, event.GetPid());
   EXPECT_EQ(4641, event.GetTid());
@@ -219,19 +219,19 @@ TEST_F(ArcTracingModelTest, Event) {
 }
 
 TEST_F(ArcTracingModelTest, EventClassification) {
-  const ArcTracingEvent event(base::JSONReader::ReadDeprecated(kTestEvent));
+  const ArcTracingEvent event(base::JSONReader::Read(kTestEvent).value());
 
-  ArcTracingEvent event_before(base::JSONReader::ReadDeprecated(kTestEvent));
+  ArcTracingEvent event_before(base::JSONReader::Read(kTestEvent).value());
   event_before.SetTimestamp(event.GetTimestamp() - event.GetDuration());
   EXPECT_EQ(ArcTracingEvent::Position::kBefore,
             event.ClassifyPositionOf(event_before));
 
-  ArcTracingEvent event_after(base::JSONReader::ReadDeprecated(kTestEvent));
+  ArcTracingEvent event_after(base::JSONReader::Read(kTestEvent).value());
   event_after.SetTimestamp(event.GetTimestamp() + event.GetDuration());
   EXPECT_EQ(ArcTracingEvent::Position::kAfter,
             event.ClassifyPositionOf(event_after));
 
-  ArcTracingEvent event_inside(base::JSONReader::ReadDeprecated(kTestEvent));
+  ArcTracingEvent event_inside(base::JSONReader::Read(kTestEvent).value());
   event_inside.SetTimestamp(event.GetTimestamp() + 1);
   event_inside.SetDuration(event.GetDuration() - 2);
   EXPECT_EQ(ArcTracingEvent::Position::kInside,
@@ -239,7 +239,7 @@ TEST_F(ArcTracingModelTest, EventClassification) {
   EXPECT_EQ(ArcTracingEvent::Position::kInside,
             event.ClassifyPositionOf(event));
 
-  ArcTracingEvent event_overlap(base::JSONReader::ReadDeprecated(kTestEvent));
+  ArcTracingEvent event_overlap(base::JSONReader::Read(kTestEvent).value());
   event_overlap.SetTimestamp(event.GetTimestamp() + 1);
   EXPECT_EQ(ArcTracingEvent::Position::kOverlap,
             event.ClassifyPositionOf(event_overlap));
@@ -254,17 +254,17 @@ TEST_F(ArcTracingModelTest, EventClassification) {
 }
 
 TEST_F(ArcTracingModelTest, EventAppendChild) {
-  ArcTracingEvent event(base::JSONReader::ReadDeprecated(kTestEvent));
+  ArcTracingEvent event(base::JSONReader::Read(kTestEvent).value());
 
   // Impossible to append the even that is bigger than target.
   std::unique_ptr<ArcTracingEvent> event_overlap =
       std::make_unique<ArcTracingEvent>(
-          base::JSONReader::ReadDeprecated(kTestEvent));
+          base::JSONReader::Read(kTestEvent).value());
   event_overlap->SetTimestamp(event.GetTimestamp() + 1);
   EXPECT_FALSE(event.AppendChild(std::move(event_overlap)));
 
   std::unique_ptr<ArcTracingEvent> event1 = std::make_unique<ArcTracingEvent>(
-      base::JSONReader::ReadDeprecated(kTestEvent));
+      base::JSONReader::Read(kTestEvent).value());
   event1->SetTimestamp(event.GetTimestamp() + 4);
   event1->SetDuration(2);
   EXPECT_TRUE(event.AppendChild(std::move(event1)));
@@ -272,7 +272,7 @@ TEST_F(ArcTracingModelTest, EventAppendChild) {
 
   // Impossible to append the event that is before last child.
   std::unique_ptr<ArcTracingEvent> event2 = std::make_unique<ArcTracingEvent>(
-      base::JSONReader::ReadDeprecated(kTestEvent));
+      base::JSONReader::Read(kTestEvent).value());
   event2->SetTimestamp(event.GetTimestamp());
   event2->SetDuration(2);
   EXPECT_FALSE(event.AppendChild(std::move(event2)));
@@ -280,7 +280,7 @@ TEST_F(ArcTracingModelTest, EventAppendChild) {
 
   // Append child to child
   std::unique_ptr<ArcTracingEvent> event3 = std::make_unique<ArcTracingEvent>(
-      base::JSONReader::ReadDeprecated(kTestEvent));
+      base::JSONReader::Read(kTestEvent).value());
   event3->SetTimestamp(event.GetTimestamp() + 5);
   event3->SetDuration(1);
   EXPECT_TRUE(event.AppendChild(std::move(event3)));
@@ -289,7 +289,7 @@ TEST_F(ArcTracingModelTest, EventAppendChild) {
 
   // Append next immediate child.
   std::unique_ptr<ArcTracingEvent> event4 = std::make_unique<ArcTracingEvent>(
-      base::JSONReader::ReadDeprecated(kTestEvent));
+      base::JSONReader::Read(kTestEvent).value());
   event4->SetTimestamp(event.GetTimestamp() + 6);
   event4->SetDuration(2);
   EXPECT_TRUE(event.AppendChild(std::move(event4)));
@@ -297,7 +297,7 @@ TEST_F(ArcTracingModelTest, EventAppendChild) {
 }
 
 TEST_F(ArcTracingModelTest, EventMatcher) {
-  const ArcTracingEvent event(base::JSONReader::ReadDeprecated(kTestEvent));
+  const ArcTracingEvent event(base::JSONReader::Read(kTestEvent).value());
   // Nothing is specified. It matches any event.
   EXPECT_TRUE(ArcTracingEventMatcher().Match(event));