arc: Switch graphics tracing tool to use ARC_VSYNC

For displaying the vsync lines in the tool, we need the ideal vsync
timestamps. The tool was using the timestamps of the HW_VSYNC_0 events,
but this could be off and very jittery by several tenths of a
millisecond from the vsync event time just because those events are
written out by SurfaceFlinger when responding to the hardware composer
vsync callback.

The hardware composer vsync callback includes the actual vsync timestamp
as an argument, but this is not included in the existing event trace in
any way.

I went and added a new ARC_VSYNC event which includes the actual vsync
timestamp in the profile data, where it is stored in the string after
the event name. Reading this event and parsing out the actual timestamp
is much more accurate.

Switching the tracing tool to using the event means that the vsync lines
will be rendered with a consistent spacing, and represent the actual
vsync times now, instead of lagging behind by some variable amount.

Specifically this change

1) Modifies arc_tracing_event_matcher to allow for a prefix match, and
   not just an exact name match. Since the timestamp is part of the name
   string and is variable, a prefix match was required to match these
   events.
2) A unit test was added to cover the new matching behavior, and in
   implementing it I went ahead and added move constructors/assignment
   to ArcTracingEvent for convenience
3) Removes "disabled-by-default-android hal" from the trace options when
   the tool is used. It turned out this was including some events from
   HIDL ("HIDL::IComposerCallback::onVsync::passthrough"), which were
   emitted using atrace_begin/atrace_end, however which could actually
   execute on separate threads and break an assumption in the tracing
   tool that they were emitted by the same thread. Perhaps the Android
   HAL generator code could be adjusted to use atrace_async_begin and
   atrace_async_end instead, but since we do not seem to need the HAL
   events, it was easier to just disable their capture.
4) Switches the tracing model to look for the ARC_VSYNC events instead
   of the HW_VSYNC_0 events, including reading the timestamp out of the
   name string instead of using the misleading event timestamp.

BUG=b:132641796
TEST=unit_tests --gtest_filter=ArcTracingEventMatcherTest*
TEST=chrome://arc-graphics-tracing

Change-Id: I887a573c74035d783b918ca69c3dbb47fc1e5920
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1811936
Auto-Submit: Lloyd Pique <lpique@chromium.org>
Reviewed-by: Steven Bennetts <stevenjb@chromium.org>
Reviewed-by: Yury Khmel <khmel@chromium.org>
Commit-Queue: Lloyd Pique <lpique@chromium.org>
Cr-Commit-Position: refs/heads/master@{#702301}

chrome/browser/chromeos/BUILD.gn

@@ -2477,6 +2477,7 @@ source_set("unit_tests") {
     "arc/tracing/arc_graphics_jank_detector_unittest.cc",
     "arc/tracing/arc_system_model_unittest.cc",
     "arc/tracing/arc_system_stat_collector_unittest.cc",
+    "arc/tracing/arc_tracing_event_matcher_unittest.cc",
     "arc/tracing/arc_tracing_model_unittest.cc",
     "arc/tracing/arc_value_event_unittest.cc",
     "arc/tts/arc_tts_service_unittest.cc",

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

@@ -65,6 +65,10 @@ ArcTracingEvent::ArcTracingEvent(base::Value dictionary)
 
 ArcTracingEvent::~ArcTracingEvent() = default;
 
+ArcTracingEvent::ArcTracingEvent(ArcTracingEvent&&) = default;
+
+ArcTracingEvent& ArcTracingEvent::operator=(ArcTracingEvent&&) = default;
+
 int ArcTracingEvent::GetPid() const {
   return GetIntegerFromDictionary(GetDictionary(), kKeyPid,
                                   0 /* default_value */);

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

@@ -32,6 +32,9 @@ class ArcTracingEvent {
   explicit ArcTracingEvent(base::Value dictionary);
   ~ArcTracingEvent();
 
+  ArcTracingEvent(ArcTracingEvent&&);
+  ArcTracingEvent& operator=(ArcTracingEvent&&);
+
   // Gets process id of the event. Returns 0 if not set.
   int GetPid() const;
   // Sets process id of the event.

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

@@ -4,6 +4,7 @@
 
 #include "chrome/browser/chromeos/arc/tracing/arc_tracing_event_matcher.h"
 
+#include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "chrome/browser/chromeos/arc/tracing/arc_tracing_event.h"
 
@@ -18,17 +19,22 @@ ArcTracingEventMatcher::ArcTracingEventMatcher(const std::string& data) {
   name_ = data.substr(position + 1);
   DCHECK(!category_.empty());
   position = name_.find('(');
-  if (position == std::string::npos)
-    return;
+  if (position != std::string::npos) {
+    DCHECK_EQ(')', name_.back());
+    for (const std::string& arg : base::SplitString(
+             name_.substr(position + 1, name_.length() - position - 2), ";",
+             base::TRIM_WHITESPACE, base::SPLIT_WANT_NONEMPTY)) {
+      std::string::size_type separator = arg.find('=');
+      args_[arg.substr(0, separator)] = arg.substr(separator + 1);
+    }
+    name_ = name_.substr(0, position);
+  }
 
-  DCHECK_EQ(')', name_.back());
-  for (const std::string& arg : base::SplitString(
-           name_.substr(position + 1, name_.length() - position - 2), ";",
-           base::TRIM_WHITESPACE, base::SPLIT_WANT_NONEMPTY)) {
-    std::string::size_type separator = arg.find('=');
-    args_[arg.substr(0, separator)] = arg.substr(separator + 1);
+  // If name_ ends with a '*', use a prefix match
+  if (!name_.empty() && name_.back() == '*') {
+    name_.pop_back();
+    name_prefix_match_ = true;
   }
-  name_ = name_.substr(0, position);
 }
 
 ArcTracingEventMatcher& ArcTracingEventMatcher::SetPhase(char phase) {
@@ -60,7 +66,9 @@ bool ArcTracingEventMatcher::Match(const ArcTracingEvent& event) const {
     return false;
   if (!category_.empty() && event.GetCategory() != category_)
     return false;
-  if (!name_.empty() && event.GetName() != name_)
+  if (!name_.empty() && !name_prefix_match_ && event.GetName() != name_)
+    return false;
+  if (name_prefix_match_ && (event.GetName().find(name_) != 0))
     return false;
   for (const auto& arg : args_) {
     if (event.GetArgAsString(arg.first, std::string() /* default_value */) !=
@@ -71,4 +79,16 @@ bool ArcTracingEventMatcher::Match(const ArcTracingEvent& event) const {
   return true;
 }
 
+base::Optional<int64_t> ArcTracingEventMatcher::ReadAndroidEventInt64(
+    const ArcTracingEvent& event) const {
+  if (!name_prefix_match_ || (event.GetName().find(name_) != 0))
+    return base::nullopt;
+
+  int64_t value = 0;
+  if (!base::StringToInt64(event.GetName().data() + name_.size(), &value))
+    return base::nullopt;
+
+  return base::make_optional(value);
+}
+
 }  // namespace arc

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

@@ -11,6 +11,7 @@
 #include <string>
 
 #include "base/macros.h"
+#include "base/optional.h"
 
 namespace arc {
 
@@ -20,14 +21,19 @@ class ArcTracingEvent;
 class ArcTracingEventMatcher {
  public:
   ArcTracingEventMatcher();
-  // Format category:name(arg_name=arg_value;..) For example:
+  // Format category:name[*]?(arg_name=arg_value;..)
+  // For example:
   // exo:Surface::Attach
   // exo:Surface::Attach(buffer_id=0x7f9f5110690)
+  // android:HW_VSYNC_0|*
   explicit ArcTracingEventMatcher(const std::string& data);
 
   // Returns true in case |event| matches criteria set.
   bool Match(const ArcTracingEvent& event) const;
 
+  base::Optional<int64_t> ReadAndroidEventInt64(
+      const ArcTracingEvent& event) const;
+
   // Sets the expected phase. Tested event does not match if its phase does not
   // match |phase|. This is an optional criteria.
   ArcTracingEventMatcher& SetPhase(char phase);
@@ -50,6 +56,8 @@ class ArcTracingEventMatcher {
   std::string category_;
   // Defines the name to match.
   std::string name_;
+  // If true, name_ is a prefix to match instead of the entire string.
+  bool name_prefix_match_ = false;
   // Defines set of arguments to match if needed.
   std::map<std::string, std::string> args_;
 

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

+// Copyright 2019 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 "chrome/browser/chromeos/arc/tracing/arc_tracing_event_matcher.h"
+#include "base/json/json_reader.h"
+#include "chrome/browser/chromeos/arc/tracing/arc_tracing_event.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace arc {
+
+namespace {
+
+ArcTracingEvent MakeEvent(const char* json_str) {
+  return ArcTracingEvent(base::JSONReader::Read(json_str).value());
+}
+
+}  // namespace
+
+using ArcTracingEventMatcherTest = testing::Test;
+
+TEST_F(ArcTracingEventMatcherTest, CategoryNameMatch) {
+  ArcTracingEventMatcher matcher("exo:Surface::Attach");
+
+  EXPECT_TRUE(
+      matcher.Match(MakeEvent(R"({"cat":"exo","name":"Surface::Attach"})")));
+  EXPECT_FALSE(
+      matcher.Match(MakeEvent(R"({"cat":"exo","name":"Surface::Attac"})")));
+  EXPECT_FALSE(
+      matcher.Match(MakeEvent(R"({"cat":"exo","name":"Surface::AttacH"})")));
+  EXPECT_FALSE(
+      matcher.Match(MakeEvent(R"({"cat":"exo","name":"Surface::Attach2"})")));
+  EXPECT_FALSE(matcher.Match(
+      MakeEvent(R"({"cat":"android","name":"Surface::Attach"})")));
+}
+
+TEST_F(ArcTracingEventMatcherTest, CategoryNamePrefixMatch) {
+  ArcTracingEventMatcher matcher("android:ARC_VSYNC|*");
+
+  EXPECT_FALSE(
+      matcher.Match(MakeEvent(R"({"cat":"android","name":"ARC_VSYNC"})")));
+  EXPECT_TRUE(
+      matcher.Match(MakeEvent(R"({"cat":"android","name":"ARC_VSYNC|"})")));
+  EXPECT_TRUE(
+      matcher.Match(MakeEvent(R"({"cat":"android","name":"ARC_VSYNC|123"})")));
+  EXPECT_TRUE(
+      matcher.Match(MakeEvent(R"({"cat":"android","name":"ARC_VSYNC|abc"})")));
+  EXPECT_FALSE(
+      matcher.Match(MakeEvent(R"({"cat":"android","name":"XARC_VSYNC|123"})")));
+}
+
+TEST_F(ArcTracingEventMatcherTest, CategoryNamePrefixAndroidInt64) {
+  ArcTracingEventMatcher matcher("android:ARC_VSYNC|*");
+
+  EXPECT_EQ(base::nullopt, matcher.ReadAndroidEventInt64(
+                               MakeEvent(R"({"name":"ARC_VSYNC"})")));
+  EXPECT_EQ(base::nullopt, matcher.ReadAndroidEventInt64(
+                               MakeEvent(R"({"name":"ARC_VSYNC|"})")));
+  EXPECT_EQ(base::nullopt, matcher.ReadAndroidEventInt64(
+                               MakeEvent(R"({"name":"ARC_VSYNC|abc"})")));
+  EXPECT_EQ(
+      base::make_optional(0),
+      matcher.ReadAndroidEventInt64(MakeEvent(R"({"name":"ARC_VSYNC|0"})")));
+  EXPECT_EQ(base::make_optional(777777777777LL),
+            matcher.ReadAndroidEventInt64(
+                MakeEvent(R"({"name":"ARC_VSYNC|777777777777"})")));
+  EXPECT_EQ(base::make_optional(-777777777777LL),
+            matcher.ReadAndroidEventInt64(
+                MakeEvent(R"({"name":"ARC_VSYNC|-777777777777"})")));
+}
+
+}  // namespace arc

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

@@ -64,12 +64,13 @@ class ArcTracingGraphicsModel {
     kChromeBarrierFlush,        // 301
 
     // Android Surface Flinger top level events.
-    kVsync = 400,                      // 400
-    kSurfaceFlingerInvalidationStart,  // 401
-    kSurfaceFlingerInvalidationDone,   // 402
-    kSurfaceFlingerCompositionStart,   // 403
-    kSurfaceFlingerCompositionDone,    // 404
-    kSurfaceFlingerCompositionJank,    // 405,
+    kSurfaceFlingerVsyncHandler = 400,  // 400
+    kSurfaceFlingerInvalidationStart,   // 401
+    kSurfaceFlingerInvalidationDone,    // 402
+    kSurfaceFlingerCompositionStart,    // 403
+    kSurfaceFlingerCompositionDone,     // 404
+    kSurfaceFlingerCompositionJank,     // 405,
+    kVsyncTimestamp,                    // 406,
 
     // Chrome OS top level events.
     kChromeOSDraw = 500,        // 500

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

@@ -183,13 +183,14 @@ TEST_F(ArcTracingModelTest, TopLevel) {
        GraphicsEventType::kSurfaceFlingerInvalidationDone,
        GraphicsEventType::kSurfaceFlingerCompositionStart,
        GraphicsEventType::kSurfaceFlingerCompositionDone}));
-  EXPECT_TRUE(ValidateGrahpicsEvents(
-      graphics_model.android_top_level().global_events(),
-      {GraphicsEventType::kVsync,
-       GraphicsEventType::kSurfaceFlingerCompositionJank}));
+  EXPECT_TRUE(
+      ValidateGrahpicsEvents(graphics_model.android_top_level().global_events(),
+                             {GraphicsEventType::kSurfaceFlingerVsyncHandler,
+                              GraphicsEventType::kSurfaceFlingerCompositionJank,
+                              GraphicsEventType::kVsyncTimestamp}));
   ASSERT_FALSE(graphics_model.android_top_level().global_events().empty());
   // Check trimmed by VSYNC.
-  EXPECT_EQ(GraphicsEventType::kVsync,
+  EXPECT_EQ(GraphicsEventType::kSurfaceFlingerVsyncHandler,
             graphics_model.android_top_level().global_events()[0].type);
   EXPECT_EQ(0U,
             graphics_model.android_top_level().global_events()[0].timestamp);

chrome/browser/resources/chromeos/arc_graphics_tracing/arc_graphics_tracing_ui.js

@@ -68,8 +68,8 @@ var eventAttributes = {
   // kChromeBarrierFlush
   301: {color: unusedColor, name: 'barrier flush'},
 
-  // kVsync
-  400: {color: '#ff3300', name: 'vsync', width: 0.5},
+  // kSurfaceFlingerVsyncHandler
+  400: {color: '#993300', name: 'vsync handler', width: 1.0},
   // kSurfaceFlingerInvalidationStart
   401: {color: '#ff9933', name: 'invalidation start'},
   // kSurfaceFlingerInvalidationDone
@@ -85,6 +85,8 @@ var eventAttributes = {
     width: 1.0,
     radius: 4.0
   },
+  // kVsyncTimestamp
+  406: {color: '#ff3300', name: 'vsync', width: 0.5},
 
   // kChromeOSDraw
   500: {color: '#3399ff', name: 'draw'},
@@ -977,7 +979,7 @@ class EventBands {
       var globalEvent = globalEvents[i];
       var globalEventType = globalEvent[0];
       var globalEventTimestamp = globalEvent[1];
-      if (globalEventType == 400 /* kVsync */) {
+      if (globalEventType == 406 /* kVsyncTimestamp */) {
         // -1 to prevent VSYNC detects itself. In last case, previous VSYNC
         // would be chosen.
         globalEventTimestamp -= 1;
@@ -1368,8 +1370,8 @@ class CpuDetailedInfoView extends DetailedInfoView {
     }
 
     var vsyncEvents = new Events(
-        overviewBand.model.android.global_events, 400 /* kVsync */,
-        400 /* kVsync */);
+        overviewBand.model.android.global_events, 406 /* kVsyncTimestamp */,
+        406 /* kVsyncTimestamp */);
     bands.setVSync(vsyncEvents);
 
     // Add center and boundary lines.
@@ -1649,7 +1651,8 @@ function setGraphicBuffersModel(model) {
   var chartHeight = 48;
 
   var vsyncEvents = new Events(
-      model.android.global_events, 400 /* kVsync */, 400 /* kVsync */);
+      model.android.global_events, 406 /* kVsyncTimestamp */,
+      406 /* kVsyncTimestamp */);
 
   var cpusTitle = new EventBandTitle(parent, 'CPUs', 'arc-events-band-title');
   var cpusBands = new CpuEventBands(
@@ -1730,6 +1733,12 @@ function setGraphicBuffersModel(model) {
       topBandPadding);
   // Add vsync events
   androidBands.setVSync(vsyncEvents);
+  // Add vsync handler events
+  var androidVsyncHandling = new Events(
+      model.android.global_events, 400 /* kSurfaceFlingerVsyncHandler */,
+      400 /* kSurfaceFlingerVsyncHandler */);
+  androidBands.addGlobal(androidVsyncHandling);
+  // Add jank events
   var androidJanks = new Events(
       model.android.global_events, 405 /* kSurfaceFlingerCompositionJank */,
       405 /* kSurfaceFlingerCompositionJank */);

chrome/browser/ui/webui/chromeos/arc_graphics_tracing/arc_graphics_tracing_handler.cc

@@ -404,7 +404,7 @@ void ArcGraphicsTracingHandler::StartTracing() {
 
   base::trace_event::TraceConfig config(
       "-*,exo,viz,toplevel,gpu,cc,blink,disabled-by-default-android "
-      "gfx,disabled-by-default-android hal,disabled-by-default-android view",
+      "gfx,disabled-by-default-android view",
       base::trace_event::RECORD_CONTINUOUSLY);
   config.EnableSystrace();
   // By default, systracing starts pre-defined set of categories with predefined