Add long latency metric for graphics smoothness alert
As part of the effort of adding Chrome graphics smoothness alert in
Perfetto, this CL implements the long latency metric that detects input
events that could potentially cause smoothness issues.
Bug: 225926753
Change-Id: Ia7960cefa8d4baa1c105dae53a57de21f27e523a
diff --git a/Android.bp b/Android.bp
index f3ebaa9..851dd94 100644
--- a/Android.bp
+++ b/Android.bp
@@ -3707,6 +3707,7 @@
"protos/perfetto/metrics/chrome/blink_gc_metric.proto",
"protos/perfetto/metrics/chrome/dropped_frames.proto",
"protos/perfetto/metrics/chrome/frame_times.proto",
+ "protos/perfetto/metrics/chrome/long_latency.proto",
"protos/perfetto/metrics/chrome/media_metric.proto",
"protos/perfetto/metrics/chrome/reported_by_page.proto",
"protos/perfetto/metrics/chrome/scroll_jank.proto",
@@ -8220,6 +8221,7 @@
"src/trace_processor/metrics/sql/chrome/touch_jank.sql",
"src/trace_processor/metrics/sql/experimental/blink_gc_metric.sql",
"src/trace_processor/metrics/sql/experimental/chrome_dropped_frames.sql",
+ "src/trace_processor/metrics/sql/experimental/chrome_long_latency.sql",
"src/trace_processor/metrics/sql/experimental/frame_times.sql",
"src/trace_processor/metrics/sql/experimental/media_metric.sql",
"src/trace_processor/metrics/sql/experimental/reported_by_page.sql",
diff --git a/BUILD b/BUILD
index 283d9ce..3550d79 100644
--- a/BUILD
+++ b/BUILD
@@ -1128,6 +1128,7 @@
"src/trace_processor/metrics/sql/chrome/touch_jank.sql",
"src/trace_processor/metrics/sql/experimental/blink_gc_metric.sql",
"src/trace_processor/metrics/sql/experimental/chrome_dropped_frames.sql",
+ "src/trace_processor/metrics/sql/experimental/chrome_long_latency.sql",
"src/trace_processor/metrics/sql/experimental/frame_times.sql",
"src/trace_processor/metrics/sql/experimental/media_metric.sql",
"src/trace_processor/metrics/sql/experimental/reported_by_page.sql",
@@ -2660,6 +2661,7 @@
"protos/perfetto/metrics/chrome/blink_gc_metric.proto",
"protos/perfetto/metrics/chrome/dropped_frames.proto",
"protos/perfetto/metrics/chrome/frame_times.proto",
+ "protos/perfetto/metrics/chrome/long_latency.proto",
"protos/perfetto/metrics/chrome/media_metric.proto",
"protos/perfetto/metrics/chrome/reported_by_page.proto",
"protos/perfetto/metrics/chrome/scroll_jank.proto",
diff --git a/protos/perfetto/metrics/chrome/BUILD.gn b/protos/perfetto/metrics/chrome/BUILD.gn
index e686114..9e88247 100644
--- a/protos/perfetto/metrics/chrome/BUILD.gn
+++ b/protos/perfetto/metrics/chrome/BUILD.gn
@@ -25,6 +25,7 @@
"blink_gc_metric.proto",
"dropped_frames.proto",
"frame_times.proto",
+ "long_latency.proto",
"media_metric.proto",
"reported_by_page.proto",
"scroll_jank.proto",
diff --git a/protos/perfetto/metrics/chrome/all_chrome_metrics.proto b/protos/perfetto/metrics/chrome/all_chrome_metrics.proto
index 2632405..4a24580 100644
--- a/protos/perfetto/metrics/chrome/all_chrome_metrics.proto
+++ b/protos/perfetto/metrics/chrome/all_chrome_metrics.proto
@@ -22,6 +22,7 @@
import "protos/perfetto/metrics/chrome/blink_gc_metric.proto";
import "protos/perfetto/metrics/chrome/dropped_frames.proto";
import "protos/perfetto/metrics/chrome/frame_times.proto";
+import "protos/perfetto/metrics/chrome/long_latency.proto";
import "protos/perfetto/metrics/chrome/media_metric.proto";
import "protos/perfetto/metrics/chrome/reported_by_page.proto";
import "protos/perfetto/metrics/chrome/scroll_jank.proto";
@@ -38,4 +39,5 @@
optional MediaMetric media_metric = 1006;
optional TouchJank touch_jank = 1007;
optional ChromeDroppedFrames chrome_dropped_frames = 1008;
+ optional ChromeLongLatency chrome_long_latency = 1009;
}
diff --git a/protos/perfetto/metrics/chrome/long_latency.proto b/protos/perfetto/metrics/chrome/long_latency.proto
new file mode 100644
index 0000000..2c5fbaf
--- /dev/null
+++ b/protos/perfetto/metrics/chrome/long_latency.proto
@@ -0,0 +1,40 @@
+/*
+ * 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.
+ */
+
+syntax = "proto2";
+
+package perfetto.protos;
+
+// Information of a frame associated with long latency input events.
+// The latency info is extracted from EventLatency slices.
+message ChromeLongLatency {
+ message LongLatency {
+ // The ending timestamp of the input event, i.e. the presentation time of
+ // the frame that contains updates triggered by the input event.
+ optional int64 ts = 1;
+
+ // The type of the input event as reported in the EventLatency slice,
+ // e.g. 'GestureScrollUpdate'.
+ optional string event_type = 2;
+
+ // The name and pid of the process where the EventLatency slice
+ // originates from.
+ optional string process_name = 3;
+ optional int64 pid = 4;
+ }
+
+ repeated LongLatency long_latency = 1;
+}
\ No newline at end of file
diff --git a/src/trace_processor/metrics/sql/BUILD.gn b/src/trace_processor/metrics/sql/BUILD.gn
index f8de2ad..fbbb41c 100644
--- a/src/trace_processor/metrics/sql/BUILD.gn
+++ b/src/trace_processor/metrics/sql/BUILD.gn
@@ -110,6 +110,7 @@
"chrome/touch_jank.sql",
"experimental/blink_gc_metric.sql",
"experimental/chrome_dropped_frames.sql",
+ "experimental/chrome_long_latency.sql",
"experimental/frame_times.sql",
"experimental/media_metric.sql",
"experimental/reported_by_page.sql",
diff --git a/src/trace_processor/metrics/sql/experimental/chrome_long_latency.sql b/src/trace_processor/metrics/sql/experimental/chrome_long_latency.sql
new file mode 100644
index 0000000..26fc2b5
--- /dev/null
+++ b/src/trace_processor/metrics/sql/experimental/chrome_long_latency.sql
@@ -0,0 +1,104 @@
+--
+-- Copyright 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
+--
+-- https://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.
+
+-- Find all long EventLatency slices > 100ms and also get the
+-- type of the event stored as 'debug.event' argument.
+-- In order to group all events
+-- Note that a long latency event is represented by the the ending time
+-- of an EventLatency slice, i.e. the timestamp of the frame presentation
+-- that reflects the event.
+DROP VIEW IF EXISTS long_eventlatency_slice;
+CREATE VIEW long_eventlatency_slice AS
+SELECT
+ ts + dur AS ts,
+ dur,
+ id,
+ track_id,
+ EXTRACT_ARG(arg_set_id, 'debug.event') AS event_type
+FROM slice WHERE name = 'EventLatency' AND dur > 100000000;
+
+-- Find the upid of the proccesses where the long latency occur.
+DROP VIEW IF EXISTS long_latency_with_upid;
+CREATE VIEW long_latency_with_upid AS
+SELECT
+ long_eventlatency_slice.ts,
+ long_eventlatency_slice.event_type,
+ process_track.upid
+FROM long_eventlatency_slice
+INNER JOIN process_track
+ON long_eventlatency_slice.track_id = process_track.id;
+
+-- Find the name and pid of the processes.
+-- Long latency events with the same timestamp and from the same process
+-- are considered one single long latency occurrence.
+DROP VIEW IF EXISTS long_latency_with_process_info;
+CREATE VIEW long_latency_with_process_info AS
+SELECT
+ long_latency_with_upid.ts,
+ long_latency_with_upid.event_type,
+ process.name AS process_name,
+ process.pid AS process_id
+FROM long_latency_with_upid
+INNER JOIN process
+ON long_latency_with_upid.upid = process.upid
+GROUP BY ts, process.pid;
+
+-- Create the derived event track for long latency.
+-- All tracks generated from chrome_long_latency_event are
+-- placed under a track group named 'Long Latency', whose summary
+-- track is the first track ('All Processes') in chrome_long_latency_event.
+-- Note that the 'All Processes' track is generated only when there are more
+-- than one source of long latency events.
+DROP VIEW IF EXISTS chrome_long_latency_event;
+CREATE VIEW chrome_long_latency_event AS
+SELECT
+ 'slice' AS track_type,
+ 'All Processes' AS track_name,
+ ts,
+ 0 AS dur,
+ event_type AS slice_name,
+ 'Long Latency' AS group_name
+FROM long_latency_with_process_info
+WHERE (SELECT COUNT(DISTINCT process_id)
+ FROM long_latency_with_process_info) > 1
+GROUP BY ts
+UNION ALL
+SELECT
+ 'slice' AS track_type,
+ process_name || ' ' || process_id AS track_name,
+ ts,
+ 0 AS dur,
+ event_type AS slice_name,
+ 'Long Latency' AS group_name
+FROM long_latency_with_process_info
+GROUP BY ts;
+
+-- Create the long latency metric output.
+DROP VIEW IF EXISTS chrome_long_latency_output;
+CREATE VIEW chrome_long_latency_output AS
+SELECT ChromeLongLatency(
+ 'long_latency', (
+ SELECT RepeatedField(
+ ChromeLongLatency_LongLatency(
+ 'ts', ts,
+ 'event_type', event_type,
+ 'process_name', process_name,
+ 'pid', process_id
+ )
+ )
+ FROM long_latency_with_process_info
+ ORDER BY ts
+ )
+);
\ No newline at end of file
diff --git a/test/trace_processor/chrome/chrome_long_latency_metric.out b/test/trace_processor/chrome/chrome_long_latency_metric.out
new file mode 100644
index 0000000..9779ed9
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_long_latency_metric.out
@@ -0,0 +1,5 @@
+
+"ts","event_type","process_name","process_id"
+200111000,"GestureScrollUpdate","Renderer",1001
+200111000,"GestureScrollUpdate","Renderer",1002
+280111001,"GestureScrollUpdate","Renderer",1001
diff --git a/test/trace_processor/chrome/chrome_long_latency_metric.sql b/test/trace_processor/chrome/chrome_long_latency_metric.sql
new file mode 100644
index 0000000..13db1ff
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_long_latency_metric.sql
@@ -0,0 +1,18 @@
+--
+-- Copyright 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
+--
+-- https://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.
+
+SELECT RUN_METRIC('experimental/chrome_long_latency.sql') AS suppress_query_output;
+
+SELECT * FROM long_latency_with_process_info;
\ No newline at end of file
diff --git a/test/trace_processor/chrome/index b/test/trace_processor/chrome/index
index 019067a..7e6856c 100644
--- a/test/trace_processor/chrome/index
+++ b/test/trace_processor/chrome/index
@@ -17,6 +17,7 @@
../track_event/track_event_counters.textproto chrome_thread_slice_repeated.sql chrome_thread_slice_repeated.out
../../data/chrome_rendering_desktop.pftrace frame_times frame_times_metric.out
../../data/chrome_rendering_desktop.pftrace chrome_dropped_frames chrome_dropped_frames_metric.out
+../chrome/long_event_latency.textproto chrome_long_latency_metric.sql chrome_long_latency_metric.out
scroll_jank_mojo_simple_watcher.py scroll_jank_mojo_simple_watcher.sql scroll_jank_mojo_simple_watcher.out
scroll_jank_gpu_check.py scroll_jank_gpu_check.sql scroll_jank_gpu_check.out
diff --git a/test/trace_processor/chrome/long_event_latency.textproto b/test/trace_processor/chrome/long_event_latency.textproto
new file mode 100644
index 0000000..8b6fa8b
--- /dev/null
+++ b/test/trace_processor/chrome/long_event_latency.textproto
@@ -0,0 +1,212 @@
+# Long latency events from two renderer processes
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 10
+ process {
+ pid: 1001
+ process_name: "Renderer"
+ }
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 20
+ process {
+ pid: 1002
+ process_name: "Renderer"
+ }
+ }
+}
+
+# EventLatency 1: 200ms duration
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 101
+ parent_uuid: 10
+ name: "EventLatency"
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 111000
+ track_event {
+ track_uuid: 101
+ categories: "cat"
+ debug_annotations: {
+ name: "event"
+ string_value: "GestureScrollUpdate"
+ }
+ name: "EventLatency"
+ type: 1
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 200111000
+ track_event {
+ track_uuid: 101
+ categories: "cat"
+ name: "EventLatency"
+ type: 2
+ }
+}
+
+# EventLatency 2: 110ms ending at the same timestamp as EventLatency 1.
+# EventLatency 1 and 2 are reported as one occurrence of long latency.
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 102
+ parent_uuid: 10
+ name: "EventLatency"
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 90111000
+ track_event {
+ track_uuid: 102
+ categories: "cat"
+ debug_annotations: {
+ name: "event"
+ string_value: "GestureScrollUpdate"
+ }
+ name: "EventLatency"
+ type: 1
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 200111000
+ track_event {
+ track_uuid: 102
+ categories: "cat"
+ name: "EventLatency"
+ type: 2
+ }
+}
+
+# EventLatency 3: a long latency slightly above the 100ms threshold
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 103
+ parent_uuid: 10
+ name: "EventLatency"
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 180111000
+ track_event {
+ track_uuid: 103
+ categories: "cat"
+ debug_annotations: {
+ name: "event"
+ string_value: "GestureScrollUpdate"
+ }
+ name: "EventLatency"
+ type: 1
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 280111001
+ track_event {
+ track_uuid: 103
+ categories: "cat"
+ name: "EventLatency"
+ type: 2
+ }
+}
+
+# EventLatency 4: below the 100ms threshold; not a long latency
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 104
+ parent_uuid: 10
+ name: "EventLatency"
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 250111001
+ track_event {
+ track_uuid: 104
+ categories: "cat"
+ debug_annotations: {
+ name: "event"
+ string_value: "GestureScrollUpdate"
+ }
+ name: "EventLatency"
+ type: 1
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 350111000
+ track_event {
+ track_uuid: 104
+ categories: "cat"
+ name: "EventLatency"
+ type: 2
+ }
+}
+
+# EventLatency 5: long latency from the second renderer process;
+# should be reported as a standalone long latency occurrence despite having
+# the same end time as EventLatency 1.
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 0
+ track_descriptor {
+ uuid: 201
+ parent_uuid: 20
+ name: "EventLatency"
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 111000
+ track_event {
+ track_uuid: 201
+ categories: "cat"
+ debug_annotations: {
+ name: "event"
+ string_value: "GestureScrollUpdate"
+ }
+ name: "EventLatency"
+ type: 1
+ }
+}
+
+packet {
+ trusted_packet_sequence_id: 1
+ timestamp: 200111000
+ track_event {
+ track_uuid: 201
+ categories: "cat"
+ name: "EventLatency"
+ type: 2
+ }
+}
\ No newline at end of file
