blob: 4ac5a90505dfd906b24efc4ef977b7cb03f6d63b [file] [log] [blame]
Joe Fernandez738fa2e2015-05-22 23:53:28 -07001page.title=Testing Display Performance
Dirk Dougherty518651c2015-05-27 20:24:37 -07002page.image=images/cards/card-test-performance_2x.png
3page.keywords=performance, fps, tools
Joe Fernandez738fa2e2015-05-22 23:53:28 -07004
5@jd:body
6
7
8<div id="qv-wrapper">
9 <div id="qv">
10 <h2>In this document</h2>
11 <ol>
12 <li><a href="#measure">Measuring UI Performance</a>
13 <ul>
14 <li><a href="#aggregate">Aggregate frame stats</a></li>
15 <li><a href="#timing-info">Precise frame timing info</a></li>
16 <li><a href="#timing-dump">Simple frame timing dump</a></li>
17 <li><a href="#collection-window">Controlling the window of stat collection</a></li>
18 <li><a href="#diagnose">Diagnosing performance regressions</a></li>
19 <li><a href="#resources">Additional resources</a></li>
20 </ul>
21 </li>
22 <li><a href="#automate">Automating UI Perfomance Tests</a>
23 <ul>
24 <li><a href="#ui-tests">Setting up UI tests</a></li>
25 <li><a href="#automated-tests">Setting up automated UI testing</a></li>
26 <li><a href="#triage">Triaging and fixing observed problems</a></li>
27 </ul>
28 </li>
29 </ol>
30 </div>
31</div>
32
33
34<p>
35 User interface (UI) performance testing ensures that your app not only meets its functional
36 requirements, but that user interactions with your app are buttery smooth, running at a
37 consistent 60 frames per second (<a href=
38 "https://www.youtube.com/watch?v=CaMTIgxCSqU&amp;index=25&amp;list=PLWz5rJ2EKKc9CBxr3BVjPTPoDPLdPIFCE">why
39 60fps?</a>), without any dropped or delayed frames, or as we like to call it, <em>jank</em>. This
40 document explains tools available to measure UI performance, and lays out an approach to
41 integrate UI performance measurements into your testing practices.
42</p>
43
44
45<h2 id="measure">Measuring UI Performance</h2>
46
47<p>
48 In order to improve performance you first need the ability to measure the performance of
49 your system, and then diagnose and identify problems that may arrive from various parts of your
50 pipeline.
51</p>
52
53<p>
54 <em><a href="https://source.android.com/devices/tech/debug/dumpsys.html">dumpsys</a></em> is an
55 Android tool that runs on the device and dumps interesting information about the status of system
56 services. Passing the <em>gfxinfo</em> command to dumpsys provides an output in logcat with
57 performance information relating to frames of animation that are occurring during the recording
58 phase.
59</p>
60
61<pre>
62&gt; adb shell dumpsys gfxinfo &lt;PACKAGE_NAME&gt;
63</pre>
64
65<p>
66 This command can produce multiple different variants of frame timing data.
67</p>
68
69<h3 id="aggregate">Aggregate frame stats</h3>
70
71<p>
72 With the M Preview the command prints out aggregated analysis of frame data to logcat, collected
73 across the entire lifetime of the process. For example:
74</p>
75
76<pre class="noprettyprint">
77Stats since: 752958278148ns
78Total frames rendered: 82189
79Janky frames: 35335 (42.99%)
8090th percentile: 34ms
8195th percentile: 42ms
8299th percentile: 69ms
83Number Missed Vsync: 4706
84Number High input latency: 142
85Number Slow UI thread: 17270
86Number Slow bitmap uploads: 1542
87Number Slow draw: 23342
88</pre>
89
90<p>
91 These high level statistics convey at a high level the rendering performance of the app, as well
92 as its stability across many frames.
93</p>
94
95
96<h3 id="timing-info">Precise frame timing info</h3>
97
98<p>
99 With the M Preview comes a new command for gfxinfo, and that’s <em>framestats</em> which provides
100 extremely detailed frame timing information from recent frames, so that you can track down and
101 debug problems more accurately.
102</p>
103
104<pre>
105&gt;adb shell dumpsys gfxinfo &lt;PACKAGE_NAME&gt; framestats
106</pre>
107
108<p>
109 This command prints out frame timing information, with nanosecond timestamps, from the last 120
110 frames produced by the app. Below is example raw output from adb dumpsys gfxinfo
111 &lt;PACKAGE_NAME&gt; framestats:
112</p>
113
114<pre class="noprettyprint">
1150,49762224585003,49762241251670,9223372036854775807,0,49762257627204,49762257646058,49762257969704,49762258002100,49762265541631,49762273951162,49762300914808,49762303675954,
1160,49762445152142,49762445152142,9223372036854775807,0,49762446678818,49762446705589,49762447268818,49762447388037,49762453551527,49762457134131,49762474889027,49762476150120,
1170,49762462118845,49762462118845,9223372036854775807,0,49762462595381,49762462619287,49762462919964,49762462968454,49762476194547,49762476483454,49762480214964,49762480911527,
1180,49762479085548,49762479085548,9223372036854775807,0,49762480066370,49762480099339,49762481013089,49762481085850,49762482232152,49762482478350,49762485657620,49762486116683,
119</pre>
120
121<p>
122 Each line of this output represents a frame produced by the app. Each line has a fixed number of
123 columns describing time spent in each stage of the frame-producing pipeline. The next section
124 describes this format in detail, including what each column represents.
125</p>
126
127
128<h4 id="fs-data-format">Framestats data format</h4>
129
130<p>
131 Since the block of data is output in CSV format, it's very straightforward to paste it to your
132 spreadsheet tool of choice, or collect and parse with a script. The following table explains the
133 format of the output data columns. All timestamps are in nanoseconds.
134</p>
135
136<ul>
137 <li>FLAGS
138 <ul>
139 <li>Rows with a ‘0’ for the FLAGS column can have their total frame time computed by
140 subtracting the INTENDED_VSYNC column from the FRAME_COMPLETED column.
141 </li>
142
143 <li>If this is non-zero the row should be ignored, as the frame has been determined as being
144 an outlier from normal performance, where it is expected that layout &amp; draw take longer
145 than 16ms. Here are a few reasons this could occur:
146 <ul>
147 <li>The window layout changed (such as the first frame of the application or after a
148 rotation)
149 </li>
150
151 <li>It is also possible the frame was skipped in which case some of the values will have
152 garbage timestamps. A frame can be skipped if for example it is out-running 60fps or if
153 nothing on-screen ended up being dirty, this is not necessarily a sign of a problem in
154 the app.
155 </li>
156 </ul>
157 </li>
158 </ul>
159 </li>
160
161 <li>VSYNC
162 <ul>
163 <li>The time value that was used in all the vsync listeners and drawing for the frame
164 (Choreographer frame callbacks, animations, View.getDrawingTime(), etc…)
165 </li>
166
167 <li>To understand more about VSYNC and how it influences your application, check out the
168 <a href=
169 "https://www.youtube.com/watch?v=1iaHxmfZGGc&amp;list=PLOU2XLYxmsIKEOXh5TwZEv89aofHzNCiu&amp;index=23">
170 Understanding VSYNC</a> video.
171 </li>
172 </ul>
173 </li>
174
175
176 <li>INTENDED_VSYNC
177 <ul>
178 <li>The intended start point for the frame. If this value is different from VSYNC, there
179 was work occurring on the UI thread that prevented it from responding to the vsync signal
180 in a timely fashion.
181 </li>
182 </ul>
183 </li>
184
185 <li>OLDEST_INPUT_EVENT
186 <ul>
187 <li>The timestamp of the oldest input event in the input queue, or Long.MAX_VALUE if
188 there were no input events for the frame.
189 </li>
190
191 <li>This value is primarily intended for platform work and has limited usefulness to app
192 developers.
193 </li>
194 </ul>
195 </li>
196
197 <li>NEWEST_INPUT_EVENT
198 <ul>
199 <li>The timestamp of the newest input event in the input queue, or 0 if there were no
200 input events for the frame.
201 </li>
202
203 <li>This value is primarily intended for platform work and has limited usefulness to app
204 developers.
205 </li>
206
207 <li>However it’s possible to get a rough idea of how much latency the app is adding by
208 looking at (FRAME_COMPLETED - NEWEST_INPUT_EVENT).
209 </li>
210 </ul>
211 </li>
212
213 <li>HANDLE_INPUT_START
214 <ul>
215 <li>The timestamp at which input events were dispatched to the application.
216 </li>
217
218 <li>By looking at the time between this and ANIMATION_START it is possible to measure how
219 long the application spent handling input events.
220 </li>
221
222 <li>If this number is high (&gt;2ms), this indicates the app is spending an unusually
223 long time processing input events, such as View.onTouchEvent(), which may indicate this
224 work needs to be optimized, or offloaded to a different thread. Note that there are some
225 scenarios, such as click events that launch new activities or similar, where it is
226 expected and acceptable that this number is large.
227 </li>
228 </ul>
229 </li>
230
231 <li>ANIMATION_START
232 <ul>
233 <li>The timestamp at which animations registered with Choreographer were run.
234 </li>
235
236 <li>By looking at the time between this and PERFORM_TRANVERSALS_START it is possible to
237 determine how long it took to evaluate all the animators (ObjectAnimator,
238 ViewPropertyAnimator, and Transitions being the common ones) that are running.
239 </li>
240
241 <li>If this number is high (&gt;2ms), check to see if your app has written any custom
242 animators or what fields ObjectAnimators are animating and ensure they are appropriate
243 for an animation.
244 </li>
245
246 <li>To learn more about Choreographer, check out the <a href=
247 "https://developers.google.com/events/io/sessions/325418001">For Butter or Worse</a>
248 video.
249 </li>
250 </ul>
251 </li>
252
253 <li>PERFORM_TRAVERSALS_START
254 <ul>
255 <li>If you subtract out DRAW_START from this value, you can extract how long the layout
256 &amp; measure phases took to complete. (note, during a scroll, or animation, you would
257 hope this should be close to zero..)
258 </li>
259
260 <li>To learn more about the measure &amp; layout phases of the rendering pipeline, check
261 out the <a href=
262 "https://www.youtube.com/watch?v=we6poP0kw6E&amp;list=PLOU2XLYxmsIKEOXh5TwZEv89aofHzNCiu&amp;index=27">
263 Invalidations, Layouts and Performance</a> video
264 </li>
265 </ul>
266 </li>
267
268 <li>DRAW_START
269 <ul>
270 <li>The time at which the draw phase of performTraversals started. This is the start
271 point of recording the display lists of any views that were invalidated.
272 </li>
273
274 <li>The time between this and SYNC_START is how long it took to call View.draw() on all
275 the invalidated views in the tree.
276 </li>
277
278 <li>For more information on the drawing model, see <a href=
279 "{@docRoot}guide/topics/graphics/hardware-accel.html#hardware-model">Hardware Acceleration</a>
280 or the <a href=
281 "https://www.youtube.com/watch?v=we6poP0kw6E&amp;list=PLOU2XLYxmsIKEOXh5TwZEv89aofHzNCiu&amp;index=27">
282 Invalidations, Layouts and Performance</a> video
283 </li>
284 </ul>
285 </li>
286
287 <li>SYNC_START
288 <ul>
289 <li>The time at which the sync phase of the drawing started.
290 </li>
291
292 <li>If the time between this and ISSUE_DRAW_COMMANDS_START is substantial (&gt;0.4ms or
293 so), it typically indicates a lot of new Bitmaps were drawn which must be uploaded to the
294 GPU.
295 </li>
296
297 <li>To understand more about the sync phase, check out the <a href=
298 "https://www.youtube.com/watch?v=VzYkVL1n4M8&amp;index=24&amp;list=PLOU2XLYxmsIKEOXh5TwZEv89aofHzNCiu">
299 Profile GPU Rendering</a> video
300 </li>
301 </ul>
302 </li>
303
304 <li>ISSUE_DRAW_COMMANDS_START
305 <ul>
306 <li>The time at which the hardware renderer started issuing drawing commands to the GPU.
307 </li>
308
309 <li>The time between this and FRAME_COMPLETED gives a rough idea of how much GPU work the
310 app is producing. Problems like too much overdraw or inefficient rendering effects show
311 up here.
312 </li>
313 </ul>
314 </li>
315
316 <li>SWAP_BUFFERS
317 <ul>
318 <li>The time at which eglSwapBuffers was called, relatively uninteresting outside of
319 platform work.
320 </li>
321 </ul>
322 </li>
323
324 <li>FRAME_COMPLETED
325 <ul>
326 <li>All done! The total time spent working on this frame can be computed by doing
327 FRAME_COMPLETED - INTENDED_VSYNC.
328 </li>
329 </ul>
330 </li>
331
332</ul>
333
334<p>
335 You can use this data in different ways. One simple but useful visualization is a
336 histogram showing the distribution of frames times (FRAME_COMPLETED - INTENDED_VSYNC) in
337 different latency buckets, see figure below. This graph tells us at a glance that most
338 frames were very good - well below the 16ms deadline (depicted in red), but a few frames
339 were significantly over the deadline. We can look at changes in this histogram over time
340 to see wholesale shifts or new outliers being created. You can also graph input latency,
341 time spent in layout, or other similar interesting metrics based on the many timestamps
342 in the data.
343</p>
344
345<img src="{@docRoot}preview/images/perf-test-framestats.png">
346
347
348<h3 id="timing-dump">Simple frame timing dump</h3>
349
350<p>
351 If <strong>Profile GPU rendering</strong> is set to <strong>In adb shell dumpsys gfxinfo</strong>
352 in Developer Options, the <code>adb shell dumpsys gfxinfo</code> command prints out timing
353 information for the most recent 120 frames, broken into a few different categories with
354 tab-separated-values. This data can be useful for indicating which parts of the drawing pipeline
355 may be slow at a high level.
356</p>
357
358<p>
359 Similar to <a href="#fs-data-format">framestats</a> above, it's very
360 straightforward to paste it to your spreadsheet tool of choice, or collect and parse with
361 a script. The following graph shows a breakdown of where many frames produced by the app
362 were spending their time.
363</p>
364
365<img src="{@docRoot}preview/images/perf-test-frame-latency.png">
366
367<p>
368 The result of running gfxinfo, copying the output, pasting it into a spreadsheet
369 application, and graphing the data as stacked bars.
370</p>
371
372<p>
373 Each vertical bar represents one frame of animation; its height represents the number of
374 milliseconds it took to compute that frame of animation. Each colored segment of the bar
375 represents a different stage of the rendering pipeline, so that you can see what parts of
376 your application may be creating a bottleneck. For more information on understanding the
377 rendering pipeline, and how to optimize for it, see the <a href=
378 "https://www.youtube.com/watch?v=we6poP0kw6E&amp;index=27&amp;list=PLWz5rJ2EKKc9CBxr3BVjPTPoDPLdPIFCE">
379 Invalidations Layouts and Performance</a> video.
380</p>
381
382
383<h3 id="collection-window">Controlling the window of stat collection</h3>
384
385<p>
386 Both the framestats and simple frame timings gather data over a very short window - about
387 two seconds worth of rendering. In order to precisely control this window of time - for
388 example, to constrain the data to a particular animation - you can reset all counters,
389 and aggregate statistics gathered.
390</p>
391
392<pre>
393&gt;adb shell dumpsys gfxinfo &lt;PACKAGE_NAME&gt; reset
394</pre>
395
396<p>
397 This can also be used in conjunction with the dumping commands themselves to collect and
398 reset at a regular cadence, capturing less-than-two-second windows of frames
399 continuously.
400</p>
401
402
403<h3 id="diagnose">Diagnosing performance regressions</h3>
404
405<p>
406 Identification of regressions is a good first step to tracking down problems, and
407 maintaining high application health. However, dumpsys just identifies the existence and
408 relative severity of problems. You still need to diagnose the particular cause of the
409 performance problems, and find appropriate ways to fix them. For that, it’s highly
410 recommended to use the <a href="{@docRoot}tools/help/systrace.html">systrace</a> tool.
411</p>
412
413
414<h3 id="resources">Additional resources</h3>
415
416<p>
417 For more information on how Android’s rendering pipeline works, common problems that you
418 can find there, and how to fix them, some of the following resources may be useful to
419 you:
420</p>
421
422<ul>
423 <li>Rendering Performance 101
424 </li>
425 <li>Why 60fps?
426 </li>
427 <li>Android UI and the GPU
428 </li>
429 <li>Invalidations Layouts and performance
430 </li>
431 <li>Analyzing UI Performance with Systrace
432 </li>
433</ul>
434
435
436<h2 id="automate">Automating UI Perfomance Tests</h2>
437
438<p>
439 One approach to UI Performance testing is to simply have a human tester perform a set of
440 user operations on the target app, and either visually look for jank, or spend an very
441 large amount of time using a tool-driven approach to find it. But this manual approach is
442 fraught with peril - human ability to perceive frame rate changes varies tremendously,
443 and this is also time consuming, tedious, and error prone.
444</p>
445
446<p>
447 A more efficient approach is to log and analyze key performance metrics from automated UI
448 tests. The Android M developer preview includes new logging capabilities which make it
449 easy to determine the amount and severity of jank in your application’s animations, and
450 that can be used to build a rigorous process to determine your current performance and
451 track future performance objectives.
452</p>
453
454<p>
455 This article walks you through a recommended approach to using that data to automate your
456 performance testing.
457</p>
458
459<p>
460 This is mostly broken down into two key actions. Firstly, identifying what you're
461 testing, and how you’re testing it. and Secondly, setting up, and maintaining an
462 automated testing environment.
463</p>
464
465
466<h3 id="ui-tests">Setting up UI tests</h3>
467
468<p>
469 Before you can get started with automated testing, it’s important to determine a few high
470 level decisions, in order to properly understand your test space, and needs you may have.
471</p>
472
473<h4>
474 Identify key animations / flows to test
475</h4>
476
477<p>
478 Remember that bad performance is most visible to users when it interrupts a smooth
479 animation. As such, when identifying what types of UI actions to test for, it’s useful to
480 focus on the key animations that users see most, or are most important to their
481 experience. For example, here are some common scenarios that may be useful to identify:
482</p>
483
484<ul>
485 <li>Scrolling a primary ListView or RecyclerView
486 </li>
487
488 <li>Animations during async wait cycles
489 </li>
490
491 <li>Any animation that may have bitmap loading / manipulation in it
492 </li>
493
494 <li>Animations including Alpha Blending
495 </li>
496
497 <li>Custom View drawing with Canvas
498 </li>
499</ul>
500
501<p>
502 Work with engineers, designers, and product managers on your team to prioritize these key
503 product animations for test coverage.
504</p>
505
506<h4>
507 Define your future objectives and track against them
508</h4>
509
510<p>
511 From a high-level, it may be critical to identify your specific performance goals, and
512 focus on writing tests, and collecting data around them. For example:
513</p>
514
515<ul>
516 <li>Do you just want to begin tracking UI performance for the first time to learn more?
517 </li>
518
519 <li>Do you want to prevent regressions that might be introduced in the future?
520 </li>
521
522 <li>Are you at 90% of smooth frames today and want to get to 98% this quarter?
523 </li>
524
525 <li>Are you at 98% smooth frames and don’t want to regress?
526 </li>
527
528 <li>Is your goal to improve performance on low end devices?
529 </li>
530</ul>
531
532<p>
533 In all of these cases, you’ll want historical tracking which shows performance across
534 multiple versions of your application.
535</p>
536
537<h4>
538 Identify devices to test on
539</h4>
540
541<p>
542 Application performance varies depending on the device it's running on. Some devices may
543 contain less memory, less powerful GPUs, or slower CPU chips. This means that animations
544 which may perform well on one set of hardware, may not on others, and worse, may be a
545 result of a bottleneck in a different part of the pipeline. So, to account for this
546 variation in what a user might see, pick a range of devices to execute tests on, both
547 current high end devices, low end devices, tablets, etc. Look for variation in CPU
548 performance, RAM, screen density, size, and so on. Tests that pass on a high end device
549 may fail on a low end device.
550</p>
551
552<h4>
553 Basic frameworks for UI Testing
554</h4>
555
556<p>
557 Tool suites like <a href=
558 "https://developer.android.com/tools/testing-support-library/index.html">UIAutomator</a>,
559 and <a href="https://code.google.com/p/android-test-kit/">Espresso</a> are built to help
560 automate the action of a user moving through your application. These are simple
561 frameworks which mimic user interaction with your device. To use these frameworks, you
562 effectively create unique scripts, which run through a set of user-actions, and play them
563 out on the device itself.
564</p>
565
566<p>
567 By combining these automated tests, alongside <code>dumpsys gfxinfo</code> you can quickly
568 create a reproducible system that allows you to execute a test, and measure the
569 performance information of that particular condition.
570</p>
571
572
573<h3 id="automated-tests">Setting up automated UI testing</h3>
574
575<p>
576 Once you have the ability to execute a UI test, and a pipeline to gather the data from a
577 single test, the next important step is to embrace a framework which can execute that
578 test multiple times, across multiple devices, and aggregate the resulting performance
579 data for further analysis by your development team.
580</p>
581
582<h4>
583 A framework for test automation
584</h4>
585
586<p>
587 It’s worth noting that UI testing frameworks (like <a href=
588 "https://developer.android.com/tools/testing-support-library/index.html">UIAutomator</a>)
589 run on the target device/emulator directly. While performance gathering information done
590 by <em>dumpsys gfxinfo</em> is driven by a host machine, sending commands over ADB. To
591 help bridge the automation of these separate entities, <a href=
592 "{@docRoot}tools/help/monkeyrunner_concepts.html">MonkeyRunner</a> framework was
593 developed; A scripting system that runs on your host machine, which can issue commands to
594 a set of connected devices, as well as receive data from them.
595</p>
596
597<p>
598 Building a set of scripts for proper Automation of UI Performance testing, at a minimum,
599 should be able to utilize monkeyRunner to accomplish the following tasks:
600</p>
601
602<ul>
603 <li>Load &amp; Launch a desired APK to a target device, devices, or emulator.
604 </li>
605
606 <li>Launch a UIAutomator UI test, and allow it to be executed
607 </li>
608
609 <li>Collect performance information through <em>dumpsys gfxinfo</em><em>.</em>
610 </li>
611
612 <li>Aggregate information and display it back in a useful fashion to the developer.
613 </li>
614</ul>
615
616
617<h3 id="triage">Triaging and fixing observed problems</h3>
618
619<p>
620 Once problem patterns or regressions are identified, the next step is identifying and
621 applying the fix. If your automated test framework preserves precise timing breakdowns
622 for frames, it can help you scrutinize recent suspicious code/layout changes (in the case
623 of regression), or narrow down the part of the system you’re analyzing when you switch to
624 manual investigation. For manual investigation, <a href=
625 "{@docRoot}tools/help/systrace.html">systrace</a> is a great place to start, showing
626 precise timing information about every stage of the rendering pipeline, every thread and
627 core in the system, as well as any custom event markers you define.
628</p>
629
630<h4>
631 Properly profiling temporal timings
632</h4>
633
634<p>
635 It is important to note the difficulties in obtaining and measuring timings that come from
636 rendering performance. These numbers are, by nature, non deterministic, and often
637 fluctuate depending on the state of the system, amount of memory available, thermal
638 throttling, and the last time a sun flare hit your area of the earth. The point is that
639 you can run the same test, twice and get slightly different numbers that may be close to
640 each other, but not exact.
641</p>
642
643<p>
644 Properly gathering and profiling data in this manner means running the same test,
645 multiple times, and accumulating the results as an average, or median value. (for the
646 sake of simplicity, let’s call this a ‘batch’) This gives you the rough approximation of
647 the performance of the test, while not needing exact timings.
648</p>
649
650<p>
651 Batches can be used between code changes to see the relative impact of those changes on
652 performance. If the average frame rate for the pre-change Batch is larger than the
653 post-change batch, then you generally have an overall win wrt performance for that
654 particular change.
655</p>
656
657<p>
658 This means that any Automated UI testing you do should take this concept into
659 consideration, and also account for any anomalies that might occur during a test. For
660 example, if your application performance suddenly dips, due to some device issue (that
661 isn’t caused by your application) then you may want to re-run the batch in order to get
662 less chaotic timings.
663</p>
664
665<p>
666 So, how many times should you run a test, before the measurements become meaningful? 10
667 times should be the minimum, with higher numbers like 50 or 100 yielding more accurate
668 results (of course, you’re now trading off time for accuracy)
669</p>