Merge "Implement more jank root causes"
diff --git a/src/trace_processor/metrics/android/android_sysui_cuj.sql b/src/trace_processor/metrics/android/android_sysui_cuj.sql
index 531ebbc..0588e52 100644
--- a/src/trace_processor/metrics/android/android_sysui_cuj.sql
+++ b/src/trace_processor/metrics/android/android_sysui_cuj.sql
@@ -51,6 +51,12 @@
JOIN last_cuj USING (upid)
WHERE thread.name = 'GPU completion'
),
+hwc_release_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 = 'HWC release'
+),
main_thread_slices AS (
SELECT slice.*, ts + dur AS ts_end
FROM slice
@@ -65,7 +71,11 @@
WHERE ts >= ts_cuj_start AND ts <= ts_cuj_end
),
gpu_completion_slices AS (
- SELECT slice.*, ts + dur AS ts_end
+ SELECT
+ slice.*,
+ ts + dur AS ts_end,
+ -- Extracts 1234 from 'waiting for GPU completion 1234'
+ CAST(STR_SPLIT(slice.name, ' ', 4) AS INTEGER) as idx
FROM slice
JOIN thread_track ON slice.track_id = thread_track.id
JOIN gpu_completion_thread USING (utid)
@@ -73,6 +83,19 @@
slice.name LIKE 'waiting for GPU completion %'
AND ts >= ts_cuj_start AND ts <= ts_cuj_end
),
+hwc_release_slices AS (
+ SELECT
+ slice.*,
+ ts + dur as ts_end,
+ -- Extracts 1234 from 'waiting for HWC release 1234'
+ CAST(STR_SPLIT(slice.name, ' ', 4) AS INTEGER) as idx
+ FROM slice
+ JOIN thread_track ON slice.track_id = thread_track.id
+ JOIN hwc_release_thread USING (utid)
+ WHERE
+ slice.name LIKE 'waiting for HWC release %'
+ AND ts >= ts_cuj_start AND ts <= ts_cuj_end
+),
frames AS (
SELECT
ROW_NUMBER() OVER (ORDER BY mts.ts) AS frame_number,
@@ -96,32 +119,32 @@
SELECT
f.frame_number,
mts.state,
- SUM(mts.dur) / 1000000 AS duration_millis,
+ SUM(mts.dur) AS dur,
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
+ HAVING mts.dur > 0
),
render_thread_state AS (
SELECT
f.frame_number,
rts.state,
- SUM(rts.dur) / 1000000 AS duration_millis,
+ SUM(rts.dur) AS dur,
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
+ HAVING rts.dur > 0
),
main_thread_binder AS (
SELECT
f.frame_number,
- SUM(mts.dur) / 1000000 AS duration_millis,
+ SUM(mts.dur) AS dur,
COUNT(*) AS call_count
FROM frames f
JOIN main_thread_slices mts
@@ -137,7 +160,7 @@
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
+ AND rts.dur > 8000000
UNION ALL
SELECT
@@ -147,28 +170,46 @@
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
+ AND rts.dur > 8000000
UNION ALL
SELECT
frame_number,
'MainThread - IO wait time' AS jank_cause
FROM main_thread_state
- WHERE state = 'DK' AND duration_millis > 8
+ WHERE state = 'DK' AND dur > 8000000
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'MainThread - scheduler' AS jank_cause
+ FROM main_thread_state
+ WHERE
+ (state = 'R' OR state = 'R+')
+ AND dur > 8000000
UNION ALL
SELECT
frame_number,
'RenderThread - IO wait time' AS jank_cause
FROM render_thread_state
- WHERE state = 'DK' AND duration_millis > 8
+ WHERE state = 'DK' AND dur > 8000000
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'RenderThread - scheduler' AS jank_cause
+ FROM render_thread_state
+ WHERE
+ (state = 'R' OR state = 'R+')
+ AND dur > 8000000
UNION ALL
SELECT
frame_number,
'MainThread - binder transaction time' AS jank_cause
FROM main_thread_binder
- WHERE duration_millis > 8
+ WHERE dur > 8000000
UNION ALL
SELECT
@@ -176,6 +217,26 @@
'MainThread - binder calls count' AS jank_cause
FROM main_thread_binder
WHERE call_count > 8
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'GPU completion - long completion time' AS jank_cause
+ FROM frames f
+ JOIN gpu_completion_slices gpu ON gpu.ts_end = f.ts_frame_end
+ LEFT JOIN hwc_release_slices hwc USING (idx)
+ WHERE (gpu.ts_end - MAX(COALESCE(hwc.ts_end, 0), gpu.ts)) > 8000000
+
+ UNION ALL
+ SELECT
+ frame_number,
+ 'Long running time' as jank_cause
+ FROM main_thread_state mts
+ JOIN render_thread_state rts USING(frame_number)
+ WHERE
+ mts.state = 'Running'
+ AND rts.state = 'Running'
+ AND mts.dur + rts.dur > 15000000
)
SELECT
AndroidSysUiCujMetrics(
diff --git a/test/trace_processor/graphics/android_sysui_cuj.out b/test/trace_processor/graphics/android_sysui_cuj.out
index c1b7163..e37dd4a 100644
--- a/test/trace_processor/graphics/android_sysui_cuj.out
+++ b/test/trace_processor/graphics/android_sysui_cuj.out
@@ -17,4 +17,17 @@
jank_cause: "MainThread - binder calls count"
jank_cause: "RenderThread - long flush layers"
}
+ frames {
+ number: 4
+ ts: 40000000
+ dur: 38000000
+ jank_cause: "GPU completion - long completion time"
+ jank_cause: "Long running time"
+ }
+ frames {
+ number: 5
+ ts: 70000000
+ dur: 18000000
+ jank_cause: "RenderThread - scheduler"
+ }
}
\ 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
index a7e6180..a336ff0 100644
--- a/test/trace_processor/graphics/android_sysui_cuj.py
+++ b/test/trace_processor/graphics/android_sysui_cuj.py
@@ -18,6 +18,7 @@
import synth_common
PID = 1000
+RTID = 1555
def add_main_thread_atrace(trace, ts, ts_end, buf):
@@ -26,8 +27,8 @@
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)
+ trace.add_atrace_begin(ts=ts, tid=RTID, pid=PID, buf=buf)
+ trace.add_atrace_end(ts=ts_end, tid=RTID, pid=PID)
def add_gpu_thread_atrace(trace, ts, ts_end, buf):
@@ -52,7 +53,7 @@
trace.add_process(pid=PID, ppid=1, cmdline="com.android.systemui", uid=10001)
trace.add_thread(
- tid=1555, tgid=PID, cmdline="RenderThread", name="RenderThread")
+ tid=RTID, tgid=PID, cmdline="RenderThread", name="RenderThread")
trace.add_thread(
tid=1666, tgid=PID, cmdline="GPU completion", name="GPU completion")
@@ -115,4 +116,41 @@
add_render_thread_atrace(
trace, ts=40_000_000, ts_end=52_000_000, buf="flush layers")
+add_frame(
+ trace,
+ ts_do_frame=40_000_000,
+ ts_end_do_frame=53_000_000,
+ ts_draw_frame=60_000_000,
+ ts_end_draw_frame=66_000_000,
+ ts_gpu=66_500_000,
+ ts_end_gpu=78_000_000)
+
+# Main thread Running for 13 millis
+trace.add_sched(ts=40_000_000, prev_pid=0, next_pid=PID)
+trace.add_sched(ts=53_000_000, prev_pid=PID, next_pid=0, prev_state='R')
+
+# RenderThread Running for 5 millis
+trace.add_sched(ts=61_000_000, prev_pid=0, next_pid=RTID)
+trace.add_sched(ts=66_000_000, prev_pid=RTID, next_pid=0, prev_state='R')
+
+add_frame(
+ trace,
+ ts_do_frame=70_000_000,
+ ts_end_do_frame=80_000_000,
+ ts_draw_frame=78_000_000,
+ ts_end_draw_frame=87_000_000,
+ ts_gpu=86_500_000,
+ ts_end_gpu=88_000_000)
+
+# Main thread Running for 1 millis
+trace.add_sched(ts=70_000_000, prev_pid=0, next_pid=PID)
+trace.add_sched(ts=71_000_000, prev_pid=PID, next_pid=0, prev_state='R')
+
+# RenderThread Running for 1 millis and R for 9.5 millis
+trace.add_sched(ts=78_000_000, prev_pid=0, next_pid=RTID)
+trace.add_sched(ts=78_500_000, prev_pid=RTID, next_pid=0, prev_state='R')
+trace.add_sched(ts=78_500_000, prev_pid=0, next_pid=0)
+trace.add_sched(ts=88_000_000, prev_pid=0, next_pid=RTID)
+trace.add_sched(ts=88_500_000, prev_pid=RTID, next_pid=0, prev_state='R')
+
sys.stdout.buffer.write(trace.trace.SerializeToString())
