Add trace metric to root cause jank in SysUI CUJs
Detects a few common jank root causes with the following caveats:
* We do not use VSYNC-app counter to determine the start
of the frame. Instead we assume the frame starts with
Choreographer#doFrame
* Thresholds for jank causes have to be adjusted
* SQL query runtime seems quite high so it has to be optimized
Bug: 161781469
Test: tools/diff_test_trace_processor.py + manual
Change-Id: I343b46e700babac95535244f797c0f7b04d9dd5c
diff --git a/Android.bp b/Android.bp
index 1027b16..9bda83d 100644
--- a/Android.bp
+++ b/Android.bp
@@ -7046,6 +7046,7 @@
"src/trace_processor/metrics/android/android_startup.sql",
"src/trace_processor/metrics/android/android_startup_launches.sql",
"src/trace_processor/metrics/android/android_surfaceflinger.sql",
+ "src/trace_processor/metrics/android/android_sysui_cuj.sql",
"src/trace_processor/metrics/android/android_task_names.sql",
"src/trace_processor/metrics/android/android_task_state.sql",
"src/trace_processor/metrics/android/android_thread_time_in_state.sql",
diff --git a/BUILD b/BUILD
index 08a8fa1..b84be89 100644
--- a/BUILD
+++ b/BUILD
@@ -794,6 +794,7 @@
"src/trace_processor/metrics/android/android_startup.sql",
"src/trace_processor/metrics/android/android_startup_launches.sql",
"src/trace_processor/metrics/android/android_surfaceflinger.sql",
+ "src/trace_processor/metrics/android/android_sysui_cuj.sql",
"src/trace_processor/metrics/android/android_task_names.sql",
"src/trace_processor/metrics/android/android_task_state.sql",
"src/trace_processor/metrics/android/android_thread_time_in_state.sql",
@@ -2132,6 +2133,7 @@
"protos/perfetto/metrics/android/process_metadata.proto",
"protos/perfetto/metrics/android/startup_metric.proto",
"protos/perfetto/metrics/android/surfaceflinger.proto",
+ "protos/perfetto/metrics/android/sysui_cuj_metrics.proto",
"protos/perfetto/metrics/android/task_names.proto",
"protos/perfetto/metrics/android/thread_time_in_state_metric.proto",
"protos/perfetto/metrics/android/unsymbolized_frames.proto",
diff --git a/protos/perfetto/metrics/android/BUILD.gn b/protos/perfetto/metrics/android/BUILD.gn
index e814a80..82eb6cb 100644
--- a/protos/perfetto/metrics/android/BUILD.gn
+++ b/protos/perfetto/metrics/android/BUILD.gn
@@ -38,6 +38,7 @@
"process_metadata.proto",
"startup_metric.proto",
"surfaceflinger.proto",
+ "sysui_cuj_metrics.proto",
"task_names.proto",
"thread_time_in_state_metric.proto",
"unsymbolized_frames.proto",
diff --git a/protos/perfetto/metrics/android/sysui_cuj_metrics.proto b/protos/perfetto/metrics/android/sysui_cuj_metrics.proto
new file mode 100644
index 0000000..589ca46
--- /dev/null
+++ b/protos/perfetto/metrics/android/sysui_cuj_metrics.proto
@@ -0,0 +1,37 @@
+/*
+ * Copyright (C) 2020 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;
+
+// Metric that stores frame information and potential jank root causes
+// for a single Android system UI interaction/user journey.
+message AndroidSysUiCujMetrics {
+ // A list of all frames within the SysUi user journey.
+ repeated Frame frames = 1;
+
+ message Frame {
+ // Index of the frame within the single user journey.
+ optional int64 number = 1;
+ optional int64 ts = 2;
+ optional int64 dur = 3;
+
+ // A list of identified potential causes for jank.
+ // Optional.
+ repeated string jank_cause = 4;
+ }
+}
diff --git a/protos/perfetto/metrics/metrics.proto b/protos/perfetto/metrics/metrics.proto
index be1094b..dfa466d 100644
--- a/protos/perfetto/metrics/metrics.proto
+++ b/protos/perfetto/metrics/metrics.proto
@@ -35,6 +35,7 @@
import "protos/perfetto/metrics/android/powrails_metric.proto";
import "protos/perfetto/metrics/android/startup_metric.proto";
import "protos/perfetto/metrics/android/surfaceflinger.proto";
+import "protos/perfetto/metrics/android/sysui_cuj_metrics.proto";
import "protos/perfetto/metrics/android/task_names.proto";
import "protos/perfetto/metrics/android/thread_time_in_state_metric.proto";
import "protos/perfetto/metrics/android/unsymbolized_frames.proto";
@@ -53,7 +54,7 @@
// Root message for all Perfetto-based metrics.
//
-// Next id: 27
+// Next id: 28
message TraceMetrics {
reserved 4, 10, 13, 14, 19;
@@ -119,6 +120,9 @@
// GPU metrics on Android.
optional AndroidGpuMetric android_gpu = 26;
+ // Frame timing and jank root causes for system UI interactions.
+ optional AndroidSysUiCujMetrics android_sysui_cuj = 27;
+
// Demo extensions.
extensions 450 to 499;
diff --git a/protos/perfetto/metrics/perfetto_merged_metrics.proto b/protos/perfetto/metrics/perfetto_merged_metrics.proto
index e09844d..cad0782 100644
--- a/protos/perfetto/metrics/perfetto_merged_metrics.proto
+++ b/protos/perfetto/metrics/perfetto_merged_metrics.proto
@@ -693,6 +693,28 @@
// End of protos/perfetto/metrics/android/surfaceflinger.proto
+// Begin of protos/perfetto/metrics/android/sysui_cuj_metrics.proto
+
+// Metric that stores frame information and potential jank root causes
+// for a single Android system UI interaction/user journey.
+message AndroidSysUiCujMetrics {
+ // A list of all frames within the SysUi user journey.
+ repeated Frame frames = 1;
+
+ message Frame {
+ // Index of the frame within the single user journey.
+ optional int64 number = 1;
+ optional int64 ts = 2;
+ optional int64 dur = 3;
+
+ // A list of identified potential causes for jank.
+ // Optional.
+ repeated string jank_cause = 4;
+ }
+}
+
+// End of protos/perfetto/metrics/android/sysui_cuj_metrics.proto
+
// Begin of protos/perfetto/metrics/android/task_names.proto
message AndroidTaskNames {
@@ -776,7 +798,7 @@
// Root message for all Perfetto-based metrics.
//
-// Next id: 27
+// Next id: 28
message TraceMetrics {
reserved 4, 10, 13, 14, 19;
@@ -842,6 +864,9 @@
// GPU metrics on Android.
optional AndroidGpuMetric android_gpu = 26;
+ // Frame timing and jank root causes for system UI interactions.
+ optional AndroidSysUiCujMetrics android_sysui_cuj = 27;
+
// Demo extensions.
extensions 450 to 499;
diff --git a/src/trace_processor/metrics/BUILD.gn b/src/trace_processor/metrics/BUILD.gn
index 6f574cd..6c844b6 100644
--- a/src/trace_processor/metrics/BUILD.gn
+++ b/src/trace_processor/metrics/BUILD.gn
@@ -52,6 +52,7 @@
"android/process_oom_score.sql",
"android/mem_stats_priority_breakdown.sql",
"android/span_view_stats.sql",
+ "android/android_sysui_cuj.sql",
"android/process_counter_span_view.sql",
"android/global_counter_span_view.sql",
"android/unsymbolized_frames.sql",
diff --git a/src/trace_processor/metrics/android/android_sysui_cuj.sql b/src/trace_processor/metrics/android/android_sysui_cuj.sql
new file mode 100644
index 0000000..531ebbc
--- /dev/null
+++ b/src/trace_processor/metrics/android/android_sysui_cuj.sql
@@ -0,0 +1,192 @@
+--
+-- Copyright 2020 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.
+
+CREATE VIEW IF NOT EXISTS android_sysui_cuj_output AS
+
+WITH last_cuj AS (
+ SELECT
+ process.name AS process_name,
+ process.upid AS upid,
+ main_thread.utid AS main_thread_utid,
+ main_thread.name AS main_thread_name,
+ thread_track.id AS main_thread_track_id,
+ slice.name AS slice_name,
+ ts AS ts_start,
+ ts + dur AS ts_end
+ FROM slice
+ JOIN process_track ON slice.track_id = process_track.id
+ JOIN process USING (upid)
+ JOIN thread AS main_thread ON main_thread.upid = process.upid AND main_thread.is_main_thread
+ JOIN thread_track USING (utid)
+ WHERE
+ slice.name LIKE 'Cuj<%>'
+ AND slice.dur > 0
+ AND process.name IN (
+ 'com.android.systemui',
+ 'com.google.android.apps.nexuslauncher')
+ ORDER BY ts desc
+ LIMIT 1
+),
+render_thread AS (
+ SELECT thread.*, last_cuj.ts_start as ts_cuj_start, last_cuj.ts_end as ts_cuj_end
+ FROM thread
+ JOIN last_cuj USING (upid)
+ WHERE thread.name = 'RenderThread'
+),
+gpu_completion_thread AS (
+ SELECT thread.*, last_cuj.ts_start as ts_cuj_start, last_cuj.ts_end as ts_cuj_end
+ FROM thread
+ JOIN last_cuj USING (upid)
+ WHERE thread.name = 'GPU completion'
+),
+main_thread_slices AS (
+ SELECT slice.*, ts + dur AS ts_end
+ FROM slice
+ JOIN last_cuj ON slice.track_id = last_cuj.main_thread_track_id
+ WHERE ts >= last_cuj.ts_start AND ts <= last_cuj.ts_end
+),
+render_thread_slices AS (
+ SELECT slice.*, ts + dur AS ts_end
+ FROM slice
+ JOIN thread_track ON slice.track_id = thread_track.id
+ JOIN render_thread USING (utid)
+ WHERE ts >= ts_cuj_start AND ts <= ts_cuj_end
+),
+gpu_completion_slices AS (
+ SELECT slice.*, ts + dur AS ts_end
+ FROM slice
+ JOIN thread_track ON slice.track_id = thread_track.id
+ JOIN gpu_completion_thread USING (utid)
+ WHERE
+ slice.name LIKE 'waiting for GPU completion %'
+ AND ts >= ts_cuj_start AND ts <= ts_cuj_end
+),
+frames AS (
+ SELECT
+ ROW_NUMBER() OVER (ORDER BY mts.ts) AS frame_number,
+ mts.ts AS ts_frame_start,
+ MIN(gcs.ts_end) AS ts_frame_end,
+ mts.ts AS ts_main_thread_start,
+ mts.ts_end AS ts_main_thread_end,
+ mts.dur AS dur_main_thread,
+ rts.ts AS ts_render_thread_start,
+ rts.ts_end AS ts_render_thread_end,
+ rts.dur AS dur_render_thread,
+ (MIN(gcs.ts_end) - mts.ts) AS dur
+ FROM main_thread_slices mts
+ JOIN render_thread_slices rts
+ ON mts.ts < rts.ts AND rts.name = 'DrawFrame'
+ JOIN gpu_completion_slices gcs ON rts.ts < gcs.ts
+ WHERE mts.name = 'Choreographer#doFrame'
+ GROUP BY mts.ts
+),
+main_thread_state AS (
+ SELECT
+ f.frame_number,
+ mts.state,
+ SUM(mts.dur) / 1000000 AS duration_millis,
+ SUM(mts.io_wait) AS io_wait
+ FROM frames f
+ JOIN thread_state mts
+ ON mts.ts >= f.ts_main_thread_start AND mts.ts < f.ts_main_thread_end
+ WHERE mts.utid = (SELECT main_thread_utid FROM last_cuj)
+ GROUP BY f.frame_number, mts.state
+ HAVING duration_millis > 0
+),
+render_thread_state AS (
+ SELECT
+ f.frame_number,
+ rts.state,
+ SUM(rts.dur) / 1000000 AS duration_millis,
+ SUM(rts.io_wait) AS io_wait
+ FROM frames f
+ JOIN thread_state rts
+ ON rts.ts >= f.ts_render_thread_start AND rts.ts < f.ts_render_thread_end
+ WHERE rts.utid in (SELECT utid FROM render_thread)
+ GROUP BY f.frame_number, rts.state
+ HAVING duration_millis > 0
+),
+main_thread_binder AS (
+ SELECT
+ f.frame_number,
+ SUM(mts.dur) / 1000000 AS duration_millis,
+ COUNT(*) AS call_count
+ FROM frames f
+ JOIN main_thread_slices mts
+ ON mts.ts >= f.ts_main_thread_start AND mts.ts < f.ts_main_thread_end
+ WHERE mts.name = 'binder transaction'
+ GROUP BY f.frame_number
+),
+jank_causes AS (
+ SELECT
+ frame_number,
+ 'RenderThread - long shader_compile' AS jank_cause
+ FROM frames f
+ JOIN render_thread_slices rts
+ ON rts.ts >= f.ts_render_thread_start AND rts.ts < f.ts_render_thread_end
+ WHERE rts.name = 'shader_compile'
+ AND rts.dur / 1000000 > 8
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'RenderThread - long flush layers' AS jank_cause
+ FROM frames f
+ JOIN render_thread_slices rts
+ ON rts.ts >= f.ts_render_thread_start AND rts.ts < f.ts_render_thread_end
+ WHERE rts.name = 'flush layers'
+ AND rts.dur / 1000000 > 8
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'MainThread - IO wait time' AS jank_cause
+ FROM main_thread_state
+ WHERE state = 'DK' AND duration_millis > 8
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'RenderThread - IO wait time' AS jank_cause
+ FROM render_thread_state
+ WHERE state = 'DK' AND duration_millis > 8
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'MainThread - binder transaction time' AS jank_cause
+ FROM main_thread_binder
+ WHERE duration_millis > 8
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'MainThread - binder calls count' AS jank_cause
+ FROM main_thread_binder
+ WHERE call_count > 8
+)
+SELECT
+ AndroidSysUiCujMetrics(
+ 'frames',
+ (SELECT RepeatedField(
+ AndroidSysUiCujMetrics_Frame(
+ 'number', f.frame_number,
+ 'ts', f.ts_frame_start,
+ 'dur', f.dur,
+ 'jank_cause',
+ (SELECT RepeatedField(jc.jank_cause)
+ FROM jank_causes jc WHERE jc.frame_number = f.frame_number)))
+ FROM frames f
+ ORDER BY frame_number ASC))
diff --git a/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor b/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor
index 411e2da..9ae40bd 100644
--- a/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor
+++ b/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor
Binary files differ
diff --git a/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor.sha1 b/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor.sha1
index 7c4dad0..378e501 100644
--- a/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor.sha1
+++ b/src/trace_processor/python/perfetto/trace_processor/metrics.descriptor.sha1
@@ -2,4 +2,4 @@
// SHA1(tools/gen_binary_descriptors)
// e5c244903aa00cad06faf3d126918306a7fe811e
// SHA1(protos/perfetto/metrics/metrics.proto)
-// 60039d709fdec334489bcb154818f9c96c554eb8
+// e4953b5f61fcf622280cb5f27e2df09a5e85dc40
diff --git a/test/synth_common.py b/test/synth_common.py
index 4398563..6a21328 100644
--- a/test/synth_common.py
+++ b/test/synth_common.py
@@ -187,10 +187,12 @@
process.uid = uid
self.proc_map[pid] = cmdline
- def add_thread(self, tid, tgid, cmdline):
+ def add_thread(self, tid, tgid, cmdline, name=None):
thread = self.packet.process_tree.threads.add()
thread.tid = tid
thread.tgid = tgid
+ if name is not None:
+ thread.name = name
self.proc_map[tid] = cmdline
def add_battery_counters(self, ts, charge_uah, cap_prct, curr_ua,
diff --git a/test/trace_processor/graphics/android_sysui_cuj.out b/test/trace_processor/graphics/android_sysui_cuj.out
new file mode 100644
index 0000000..c1b7163
--- /dev/null
+++ b/test/trace_processor/graphics/android_sysui_cuj.out
@@ -0,0 +1,20 @@
+android_sysui_cuj {
+ frames {
+ number: 1
+ ts: 0
+ dur: 15000000
+ }
+ frames {
+ number: 2
+ ts: 8000000
+ dur: 27000000
+ jank_cause: "MainThread - binder transaction time"
+ }
+ frames {
+ number: 3
+ ts: 30000000
+ dur: 28000000
+ jank_cause: "MainThread - binder calls count"
+ jank_cause: "RenderThread - long flush layers"
+ }
+}
\ No newline at end of file
diff --git a/test/trace_processor/graphics/android_sysui_cuj.py b/test/trace_processor/graphics/android_sysui_cuj.py
new file mode 100644
index 0000000..a7e6180
--- /dev/null
+++ b/test/trace_processor/graphics/android_sysui_cuj.py
@@ -0,0 +1,118 @@
+#!/usr/bin/env python3
+# Copyright (C) 2020 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
+
+PID = 1000
+
+
+def add_main_thread_atrace(trace, ts, ts_end, buf):
+ trace.add_atrace_begin(ts=ts, tid=PID, pid=PID, buf=buf)
+ trace.add_atrace_end(ts=ts_end, tid=PID, pid=PID)
+
+
+def add_render_thread_atrace(trace, ts, ts_end, buf):
+ trace.add_atrace_begin(ts=ts, tid=1555, pid=PID, buf=buf)
+ trace.add_atrace_end(ts=ts_end, tid=1555, pid=PID)
+
+
+def add_gpu_thread_atrace(trace, ts, ts_end, buf):
+ trace.add_atrace_begin(ts=ts, tid=1666, pid=PID, buf=buf)
+ trace.add_atrace_end(ts=ts_end, tid=1666, pid=PID)
+
+
+def add_frame(trace, ts_do_frame, ts_end_do_frame, ts_draw_frame,
+ ts_end_draw_frame, ts_gpu, ts_end_gpu):
+ add_main_thread_atrace(trace, ts_do_frame, ts_end_do_frame,
+ "Choreographer#doFrame")
+ add_render_thread_atrace(trace, ts_draw_frame, ts_end_draw_frame, "DrawFrame")
+ add_gpu_thread_atrace(trace, ts_gpu, ts_end_gpu,
+ "waiting for GPU completion 123")
+
+
+trace = synth_common.create_trace()
+
+trace.add_packet()
+trace.add_package_list(
+ ts=0, name="com.android.systemui", uid=10001, version_code=1)
+
+trace.add_process(pid=PID, ppid=1, cmdline="com.android.systemui", uid=10001)
+trace.add_thread(
+ tid=1555, tgid=PID, cmdline="RenderThread", name="RenderThread")
+trace.add_thread(
+ tid=1666, tgid=PID, cmdline="GPU completion", name="GPU completion")
+
+trace.add_ftrace_packet(cpu=0)
+trace.add_atrace_async_begin(ts=0, tid=PID, pid=PID, buf="Cuj<5>")
+trace.add_atrace_async_end(ts=1_000_000_000, tid=PID, pid=PID, buf="Cuj<5>")
+
+add_frame(
+ trace,
+ ts_do_frame=0,
+ ts_end_do_frame=5_000_000,
+ ts_draw_frame=4_000_000,
+ ts_end_draw_frame=5_000_000,
+ ts_gpu=10_000_000,
+ ts_end_gpu=15_000_000)
+add_main_thread_atrace(
+ trace, ts=1_500_000, ts_end=2_000_000, buf="binder transaction")
+add_render_thread_atrace(
+ trace, ts=4_500_000, ts_end=4_800_000, buf="flush layers")
+
+add_frame(
+ trace,
+ ts_do_frame=8_000_000,
+ ts_end_do_frame=23_000_000,
+ ts_draw_frame=22_000_000,
+ ts_end_draw_frame=26_000_000,
+ ts_gpu=27_500_000,
+ ts_end_gpu=35_000_000)
+add_main_thread_atrace(
+ trace, ts=9_000_000, ts_end=20_000_000, buf="binder transaction")
+add_render_thread_atrace(
+ trace, ts=24_000_000, ts_end=25_000_000, buf="flush layers")
+
+add_frame(
+ trace,
+ ts_do_frame=30_000_000,
+ ts_end_do_frame=33_000_000,
+ ts_draw_frame=34_000_000,
+ ts_end_draw_frame=56_000_000,
+ ts_gpu=57_500_000,
+ ts_end_gpu=58_000_000)
+add_main_thread_atrace(
+ trace, ts=31_000_000, ts_end=31_050_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_100_000, ts_end=31_150_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_200_000, ts_end=31_250_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_300_000, ts_end=31_350_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_400_000, ts_end=31_450_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_500_000, ts_end=31_550_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_600_000, ts_end=31_650_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_700_000, ts_end=31_750_000, buf="binder transaction")
+add_main_thread_atrace(
+ trace, ts=31_800_000, ts_end=31_850_000, buf="binder transaction")
+add_render_thread_atrace(
+ trace, ts=40_000_000, ts_end=52_000_000, buf="flush layers")
+
+sys.stdout.buffer.write(trace.trace.SerializeToString())
diff --git a/test/trace_processor/graphics/index b/test/trace_processor/graphics/index
index 6d3c85e..f830cd9 100644
--- a/test/trace_processor/graphics/index
+++ b/test/trace_processor/graphics/index
@@ -22,3 +22,6 @@
# GPU metrics
gpu_metric.py android_gpu gpu_metric.out
+
+# Android SysUI CUJs metrics
+android_sysui_cuj.py android_sysui_cuj android_sysui_cuj.out