1#!/usr/bin/env python3 2# Copyright (C) 2020 The Android Open Source Project 3# 4# Licensed under the Apache License, Version 2.0 (the "License"); 5# you may not use this file except in compliance with the License. 6# You may obtain a copy of the License at 7# 8# http://www.apache.org/licenses/LICENSE-2.0 9# 10# Unless required by applicable law or agreed to in writing, software 11# distributed under the License is distributed on an "AS IS" BASIS, 12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13# See the License for the specific language governing permissions and 14# limitations under the License. 15 16from lib2to3.pgen2 import token 17from os import sys, path 18 19import synth_common 20 21PID = 1000 22RTID = 1555 23JITID = 1777 24LAYER = "TX - NotificationShade#0" 25 26 27def add_main_thread_atrace(trace, ts, ts_end, buf): 28 trace.add_atrace_begin(ts=ts, tid=PID, pid=PID, buf=buf) 29 trace.add_atrace_end(ts=ts_end, tid=PID, pid=PID) 30 31 32def add_render_thread_atrace_begin(trace, ts, buf): 33 trace.add_atrace_begin(ts=ts, tid=RTID, pid=PID, buf=buf) 34 35 36def add_render_thread_atrace_end(trace, ts_end): 37 trace.add_atrace_end(ts=ts_end, tid=RTID, pid=PID) 38 39 40def add_render_thread_atrace(trace, ts, ts_end, buf): 41 add_render_thread_atrace_begin(trace, ts, buf) 42 add_render_thread_atrace_end(trace, ts_end) 43 44 45def add_gpu_thread_atrace(trace, ts, ts_end, buf): 46 trace.add_atrace_begin(ts=ts, tid=1666, pid=PID, buf=buf) 47 trace.add_atrace_end(ts=ts_end, tid=1666, pid=PID) 48 49 50def add_jit_thread_atrace(trace, ts, ts_end, buf): 51 trace.add_atrace_begin(ts=ts, tid=JITID, pid=PID, buf=buf) 52 trace.add_atrace_end(ts=ts_end, tid=JITID, pid=PID) 53 54 55def add_frame(trace, 56 vsync, 57 ts_do_frame, 58 ts_end_do_frame, 59 ts_draw_frame, 60 ts_end_draw_frame, 61 ts_gpu=None, 62 ts_end_gpu=None): 63 add_main_thread_atrace(trace, ts_do_frame, ts_end_do_frame, 64 "Choreographer#doFrame %d" % vsync) 65 66 gpu_idx = 1000 + vsync * 10 + 1 67 if ts_gpu is None: 68 gpu_fence_message = "GPU completion fence %d has signaled" 69 else: 70 gpu_fence_message = "Trace GPU completion fence %d" 71 add_render_thread_atrace_begin(trace, ts_draw_frame, "DrawFrames %d" % vsync) 72 add_render_thread_atrace(trace, ts_end_draw_frame - 100, 73 ts_end_draw_frame - 1, gpu_fence_message % gpu_idx) 74 add_render_thread_atrace_end(trace, ts_end_draw_frame) 75 76 if ts_gpu is not None: 77 add_gpu_thread_atrace(trace, ts_gpu, ts_end_gpu, 78 "waiting for GPU completion %d" % gpu_idx) 79 80 81def add_expected_frame_events(ts, dur, token_start): 82 trace.add_expected_display_frame_start_event( 83 ts=ts, cookie=token_start, token=token_start, pid=PID) 84 trace.add_frame_end_event(ts=ts + dur, cookie=token_start) 85 86 87def add_actual_frame_events(ts, 88 dur, 89 token_start, 90 cookie=None, 91 jank=None, 92 on_time_finish_override=None): 93 if cookie is None: 94 cookie = token_start + 1 95 jank_type = jank if jank is not None else 1 96 present_type = 2 if jank is not None else 1 97 if on_time_finish_override is None: 98 on_time_finish = 1 if jank is None else 0 99 else: 100 on_time_finish = on_time_finish_override 101 trace.add_actual_display_frame_start_event( 102 ts=ts, 103 cookie=cookie, 104 token=token_start, 105 pid=PID, 106 present_type=present_type, 107 on_time_finish=on_time_finish, 108 gpu_composition=0, 109 jank_type=jank_type, 110 prediction_type=3) 111 trace.add_frame_end_event(ts=ts + dur, cookie=cookie) 112 113 114trace = synth_common.create_trace() 115 116trace.add_packet() 117trace.add_package_list( 118 ts=0, name="com.android.systemui", uid=10001, version_code=1) 119 120trace.add_process(pid=PID, ppid=1, cmdline="com.android.systemui", uid=10001) 121trace.add_thread( 122 tid=RTID, tgid=PID, cmdline="RenderThread", name="RenderThread") 123trace.add_thread( 124 tid=1666, tgid=PID, cmdline="GPU completion", name="GPU completion") 125trace.add_thread( 126 tid=JITID, tgid=PID, cmdline="Jit thread pool", name="Jit thread pool") 127trace.add_ftrace_packet(cpu=0) 128trace.add_atrace_async_begin(ts=10, tid=PID, pid=PID, buf="J<SHADE_ROW_EXPAND>") 129trace.add_atrace_async_end( 130 ts=901_000_010, tid=PID, pid=PID, buf="J<SHADE_ROW_EXPAND>") 131 132add_frame( 133 trace, 134 vsync=10, 135 ts_do_frame=0, 136 ts_end_do_frame=5_000_000, 137 ts_draw_frame=4_000_000, 138 ts_end_draw_frame=5_000_000, 139 ts_gpu=10_000_000, 140 ts_end_gpu=15_000_000) 141add_main_thread_atrace( 142 trace, ts=1_500_000, ts_end=2_000_000, buf="binder transaction") 143add_render_thread_atrace( 144 trace, ts=4_500_000, ts_end=4_800_000, buf="flush layers") 145 146 147add_frame( 148 trace, 149 vsync=20, 150 ts_do_frame=20_000_000, 151 ts_end_do_frame=23_000_000, 152 ts_draw_frame=22_000_000, 153 ts_end_draw_frame=26_000_000, 154 ts_gpu=27_500_000, 155 ts_end_gpu=35_000_000) 156add_main_thread_atrace( 157 trace, ts=9_000_000, ts_end=19_000_000, buf="binder transaction") 158add_render_thread_atrace( 159 trace, ts=24_000_000, ts_end=25_000_000, buf="flush layers") 160 161add_frame( 162 trace, 163 vsync=30, 164 ts_do_frame=30_000_000, 165 ts_end_do_frame=33_000_000, 166 ts_draw_frame=31_000_000, 167 ts_end_draw_frame=50_000_000, 168 ts_gpu=51_500_000, 169 ts_end_gpu=52_000_000) 170add_main_thread_atrace( 171 trace, ts=31_000_000, ts_end=31_050_000, buf="binder transaction") 172add_main_thread_atrace( 173 trace, ts=31_100_000, ts_end=31_150_000, buf="binder transaction") 174add_main_thread_atrace( 175 trace, ts=31_200_000, ts_end=31_250_000, buf="binder transaction") 176add_main_thread_atrace( 177 trace, ts=31_300_000, ts_end=31_350_000, buf="binder transaction") 178add_main_thread_atrace( 179 trace, ts=31_400_000, ts_end=31_450_000, buf="binder transaction") 180add_main_thread_atrace( 181 trace, ts=31_500_000, ts_end=31_550_000, buf="binder transaction") 182add_main_thread_atrace( 183 trace, ts=31_600_000, ts_end=31_650_000, buf="binder transaction") 184add_main_thread_atrace( 185 trace, ts=31_700_000, ts_end=31_750_000, buf="binder transaction") 186add_main_thread_atrace( 187 trace, ts=31_800_000, ts_end=31_850_000, buf="binder transaction") 188add_render_thread_atrace( 189 trace, ts=38_000_000, ts_end=50_000_000, buf="flush layers") 190 191add_frame( 192 trace, 193 vsync=40, 194 ts_do_frame=40_000_000, 195 ts_end_do_frame=53_000_000, 196 ts_draw_frame=52_000_000, 197 ts_end_draw_frame=59_000_000, 198 ts_gpu=66_500_000, 199 ts_end_gpu=78_000_000) 200 201add_jit_thread_atrace( 202 trace, 203 ts=39_000_000, 204 ts_end=45_000_000, 205 buf="JIT compiling void aa.aa(java.lang.Object, bb) (kind=Baseline)") 206add_jit_thread_atrace( 207 trace, 208 ts=46_000_000, 209 ts_end=47_000_000, 210 buf="Lock contention on Jit code cache (owner tid: 12345)") 211add_jit_thread_atrace( 212 trace, 213 ts=52_500_000, 214 ts_end=54_000_000, 215 buf="JIT compiling void cc.bb(java.lang.Object, bb) (kind=Osr)") 216add_jit_thread_atrace( 217 trace, 218 ts=56_500_000, 219 ts_end=60_000_000, 220 buf="JIT compiling void ff.zz(java.lang.Object, bb) (kind=Baseline)") 221 222# Main thread Running for 14 millis 223trace.add_sched(ts=39_000_000, prev_pid=0, next_pid=PID) 224trace.add_sched(ts=53_000_000, prev_pid=PID, next_pid=0, prev_state='R') 225 226# RenderThread Running for 5 millis 227trace.add_sched(ts=54_000_000, prev_pid=0, next_pid=RTID) 228trace.add_sched(ts=59_000_000, prev_pid=RTID, next_pid=0, prev_state='R') 229 230add_frame( 231 trace, 232 vsync=60, 233 ts_do_frame=70_000_000, 234 ts_end_do_frame=80_000_000, 235 ts_draw_frame=78_000_000, 236 ts_end_draw_frame=87_000_000, 237 ts_gpu=86_500_000, 238 ts_end_gpu=88_000_000) 239 240# Main thread Running for 1 millis 241trace.add_sched(ts=70_000_000, prev_pid=0, next_pid=PID) 242trace.add_sched(ts=71_000_000, prev_pid=PID, next_pid=0, prev_state='R') 243 244# RenderThread Running for 1 millis and R for 9.5 millis 245trace.add_sched(ts=78_000_000, prev_pid=0, next_pid=RTID) 246trace.add_sched(ts=78_500_000, prev_pid=RTID, next_pid=0, prev_state='R') 247trace.add_sched(ts=78_500_000, prev_pid=0, next_pid=0) 248trace.add_sched(ts=88_000_000, prev_pid=0, next_pid=RTID) 249trace.add_sched(ts=88_500_000, prev_pid=RTID, next_pid=0, prev_state='R') 250 251add_frame( 252 trace, 253 vsync=90, 254 ts_do_frame=100_000_000, 255 ts_end_do_frame=115_000_000, 256 ts_draw_frame=102_000_000, 257 ts_end_draw_frame=104_000_000, 258 ts_gpu=108_000_000, 259 ts_end_gpu=115_600_000) 260 261add_render_thread_atrace_begin(trace, ts=108_000_000, buf="DrawFrames 90") 262add_render_thread_atrace( 263 trace, 264 ts=113_000_000, 265 ts_end=113_500_000, 266 buf="Trace GPU completion fence 1902") 267add_render_thread_atrace_end(trace, ts_end=114_000_000) 268 269add_gpu_thread_atrace( 270 trace, 271 ts=121_500_000, 272 ts_end=122_000_000, 273 buf="waiting for GPU completion 1902") 274 275add_frame( 276 trace, 277 vsync=100, 278 ts_do_frame=200_000_000, 279 ts_end_do_frame=215_000_000, 280 ts_draw_frame=202_000_000, 281 ts_end_draw_frame=204_000_000, 282 ts_gpu=208_000_000, 283 ts_end_gpu=210_000_000) 284 285add_render_thread_atrace( 286 trace, ts=208_000_000, ts_end=214_000_000, buf="DrawFrames 100") 287 288add_frame( 289 trace, 290 vsync=110, 291 ts_do_frame=300_000_000, 292 ts_end_do_frame=315_000_000, 293 ts_draw_frame=302_000_000, 294 ts_end_draw_frame=304_000_000, 295 ts_gpu=None, 296 ts_end_gpu=None) 297 298add_render_thread_atrace( 299 trace, ts=305_000_000, ts_end=308_000_000, buf="dispatchFrameCallbacks") 300 301add_frame( 302 trace, 303 vsync=120, 304 ts_do_frame=400_000_000, 305 ts_end_do_frame=415_000_000, 306 ts_draw_frame=402_000_000, 307 ts_end_draw_frame=404_000_000, 308 ts_gpu=408_000_000, 309 ts_end_gpu=410_000_000) 310 311add_render_thread_atrace( 312 trace, ts=415_000_000, ts_end=418_000_000, buf="dispatchFrameCallbacks") 313 314# Frame start delayed by 50ms by a long binder transaction 315add_main_thread_atrace( 316 trace, ts=500_000_000, ts_end=549_500_000, buf="binder transaction") 317 318add_frame( 319 trace, 320 vsync=130, 321 ts_do_frame=550_000_000, 322 ts_end_do_frame=555_000_000, 323 ts_draw_frame=552_000_000, 324 ts_end_draw_frame=556_000_000, 325 ts_gpu=None, 326 ts_end_gpu=None) 327 328# Frame start delayed by 8ms by a long binder transaction 329add_main_thread_atrace( 330 trace, ts=600_000_000, ts_end=608_049_000, buf="binder transaction") 331 332add_frame( 333 trace, 334 vsync=140, 335 ts_do_frame=608_500_000, 336 ts_end_do_frame=610_000_000, 337 ts_draw_frame=609_000_000, 338 ts_end_draw_frame=626_000_000, 339 ts_gpu=None, 340 ts_end_gpu=None) 341 342# One more frame after the CUJ is finished 343add_frame( 344 trace, 345 vsync=140, 346 ts_do_frame=1_100_000_000, 347 ts_end_do_frame=1_200_000_000, 348 ts_draw_frame=1_150_000_000, 349 ts_end_draw_frame=1_300_000_000, 350 ts_gpu=1_400_000_000, 351 ts_end_gpu=1_500_000_000) 352 353add_expected_frame_events(ts=0, dur=16_000_000, token_start=10) 354add_actual_frame_events(ts=0, dur=16_000_000, token_start=10) 355 356add_expected_frame_events(ts=8_000_000, dur=20_000_000, token_start=20) 357add_actual_frame_events(ts=8_000_000, dur=28_000_000, token_start=20, jank=66) 358 359add_expected_frame_events(ts=30_000_000, dur=20_000_000, token_start=30) 360add_actual_frame_events(ts=30_000_000, dur=25_000_000, token_start=30, jank=64) 361 362add_expected_frame_events(ts=40_000_000, dur=20_000_000, token_start=40) 363add_actual_frame_events(ts=40_000_000, dur=40_000_000, token_start=40, jank=64) 364 365add_expected_frame_events(ts=70_000_000, dur=20_000_000, token_start=60) 366add_actual_frame_events(ts=70_000_000, dur=10_000_000, token_start=60, jank=64) 367add_actual_frame_events( 368 ts=70_000_000, dur=20_000_000, token_start=60, cookie=62, jank=64) 369 370add_expected_frame_events(ts=100_000_000, dur=20_000_000, token_start=90) 371add_actual_frame_events(ts=100_000_000, dur=23_000_000, token_start=90, jank=64) 372 373add_expected_frame_events(ts=200_000_000, dur=20_000_000, token_start=100) 374add_actual_frame_events( 375 ts=200_000_000, dur=22_000_000, token_start=100, jank=34) 376 377add_expected_frame_events(ts=300_000_000, dur=20_000_000, token_start=110) 378add_actual_frame_events(ts=300_000_000, dur=61_000_000, token_start=110) 379 380add_expected_frame_events(ts=400_000_000, dur=20_000_000, token_start=120) 381add_actual_frame_events( 382 ts=400_000_000, 383 dur=61_000_000, 384 token_start=120, 385 jank=128, 386 on_time_finish_override=1) 387 388# Multiple layers but only one of them janked (the one we care about) 389add_expected_frame_events(ts=500_000_000, dur=20_000_000, token_start=130) 390add_actual_frame_events(ts=500_000_000, dur=2_000_000, token_start=130) 391add_actual_frame_events( 392 ts=550_000_000, dur=6_000_000, token_start=130, cookie=132, jank=64) 393 394# Single layer but actual frame event is slighly after doFrame start 395add_expected_frame_events(ts=600_000_000, dur=20_000_000, token_start=140) 396add_actual_frame_events( 397 ts=608_600_000, dur=17_000_000, token_start=140, jank=64) 398 399add_expected_frame_events(ts=1_100_000_000, dur=20_000_000, token_start=1000) 400add_actual_frame_events( 401 ts=1_100_000_000, dur=500_000_000, token_start=1000, jank=64) 402 403sys.stdout.buffer.write(trace.trace.SerializeToString()) 404