Home > Articles > Mobile Application Development & Programming

  • Print
  • + Share This
This chapter is from the book

Using Systrace to Understand Jank

This is a good way to see when the problems happen and you might have some sense of what is going on as you scroll and see the spikes, but it doesn’t help much with narrowing down exactly what’s going on. That’s where the Systrace tool comes in. Systrace logs a significant amount of data about what’s going on while it is running and outputs the data as an interactive HTML file. Typically you run it for a brief time (say, 5 seconds), interacting with the app during that time to reproduce the jank, and then you analyze the created HTML file to understand what was taking so long that frames were dropped. Note that not all devices have Systrace available, so it’s best used on Nexus devices.

You may recall that in Chapter 8, “Applying the Design,” we called out the jank created during scrolling on the main screen of the app. Now it’s time to come back to that issue, track down what exactly was causing it with Systrace, and fix it. First, we know that the jank seemed most noticeable when a new item was coming onto the screen. To make this easier to test, we’re going to increase the verticalSpacing attribute in the GridView within fragment_tool_grid.xml from 16dp to 200dp. This will add enough spacing between items that only about two rows show up on a typical phone, which means two rows are off screen and can be scrolled on to create jank. One of the most important parts of fixing any bug, whether it’s a crash or just a UI hiccup, is being able to easily reproduce it so that you can verify your changes fix it.

First, we can run Systrace without making any other changes. Open Android Device Monitor (under the Tools menu and the Android submenu). You should see your device in the Devices tab on the left. Select it and then pick the confusing Systrace icon above (called out in Figure 10.2). The next window, shown in Figure 10.3, allows you to configure Systrace. Be sure to pick a reasonable name and location. The default 5 seconds and buffer size are both typically fine. You must enable application traces from the app by clicking the dropdown and pick the package name of the app if you want to use any additional logging within your app (it’s a good habit to select your app every time). If you don’t see the app, be sure that you’ve selected the correct device and you’ve installed a debug version of the app (the default build type in Android Studio is a debug build).

Figure 10.2

Figure 10.2 The Systrace icon in Android Device Monitor

Figure 10.3

Figure 10.3 The Systrace configuration dialog

Systrace works by tracking the starting and stopping points of events. The events are identified by strings called tags. Android has several built in that are enabled by default as well as some advanced ones that are typically off. For now, leave the commonly used tags all enabled and turn on RenderScript in the advanced options below (remember, we used RenderScript to blur the portion of the image behind the text).

When you click OK, you’ll see a dialog informing you that it is collecting trace information. Sometimes it can help to wait briefly (1–2 seconds) before interacting and then start interacting with the app to reproduce the jank. The wait lets you create a baseline for how long events take when there is no interaction, but it’s up to you whether that’s useful. Once the time is up, the data is pulled off the device and the HTML file is generated (Systrace currently doesn’t tell you that everything is ready; the dialog just goes away and the file appears where you specified). Open it in your browser and prepare to be confused. You should see something like Figure 10.4 in your browser.

Figure 10.4

Figure 10.4 The Systrace output in a browser

The HTML will display as a bunch of colorful lines and boxes that make no sense at first. The display shows time along the X-axis and various events along the Y-axis. The wider a box is, the longer it took to perform that operation. At the top will be the CPU info, if you had that enabled. Then you’ll have various info, much of which won’t be useful to you right now. Further down, you will see “surfaceflinger.” SurfaceFlinger takes buffers of pixel data, composites them, and then pushes them to the display. Big gaps in the SurfaceFlinger section when the UI should have been changing (such as while scrolling) are generally problems, but we can scroll down more to the app (the name should be on the left, though it is often cut off for longer names) for more detail.

The controls for the Systrace HTML page are not particularly user friendly. Pretend your Systrace output is as exciting as a first-person shooter and put your fingers on the W, A, S, and D keys. The W and S keys zoom in and out, respectively, while the A and D keys pan. You can also click and drag the mouse up or down to zoom. Double-clicking the mouse creates a guideline under the mouse that you can then position by clicking where you want it. Once you’ve placed more two guidelines or more, you can see the time between them at the top. At time of writing, the documentation for Systrace is outdated, so the best source for learning the bizarre controls is by clicking the question mark at the very top right when viewing a Systrace file.

Scroll down to the woodworking tools app (it should be the largest section) as shown in Figure 10.5. If you see several huge sections such as obtainView that report they never finished, then Systrace is lying to you. The way the tool works is very simple. Each time a developer wants to track something (including the events that are tracked inside of Android itself), the developer uses the Trace class (made available to application developers in Android 4.3; you can also use TraceCompat from the support library), calling beginSection. When you begin a new section, you give it a name, which shows up in the colored bars here. When that event you were tracking is done, you call endSection. Simple, right? The problem is that ending a section always ends the most recently started section. This means that if you forget to call endSection such as when you bail out of a method early due to an exception, your section will not end at the right time, if at all. There are a few places where this can happen in the Android system code, unfortunately, so you can receive Systrace output that tells you something like obtainView did not finish when you know it did (the view appeared on the screen).

Figure 10.5

Figure 10.5 The Systrace output showing the app events

Fortunately, you can “fix” the output of Systrace yourself by calling endSection where it was missing. If you see this bug, then after each call to the static createFromBitmap method of Allocation, call TraceCompat’s endSection method. This fixes the missing calls in Allocation (a bug fix has been accepted for this in the Android source code itself, but it hasn’t yet made it into a major release) and now you can run Systrace again. Scrolling down to the woodworking tools app, you should now see only a few rows with most of the entries significantly smaller than they were. The areas where each tracked section is just a sliver are generally good (remember, the X-axis is time) and the larger ones are generally bad. If you use W on your keyboard (or click and drag up), you can zoom in on one of those bigger sections. Double-clicking with the mouse will begin the placement of a timing guideline that you can then position by moving the mouse and place by clicking. Creating two of these will tell you the time between them. Figure 10.6 shows that one of the obtainView sections took 155 milliseconds, which is more than eight frames! Keep in mind the power of the device you’re testing on as well. In this case, the test was on a Nexus 5. A Nexus 6 might not drop as many frames (a quick test shows it closer to 90 milliseconds), but the Nexus 5 is still in the middle range of Android devices (especially when you look at markets across the world).

Figure 10.6

Figure 10.6 Analyzing the details of the Systrace output

The obtainView section we’ve been looking at comes from AbsListView’s package-private method of the same name. Because we can be reasonably sure that the Android system code around this is fast, the problem is within the getView method of our ToolGridAdapter. In the Systrace output, we can also see that the image for the view is being decoded and that alone is taking almost four frames; looking closer, you can see the image is being decoded twice! Just fixing this issue will cut the total obtainView time almost in half.

Within the getView method, we call the setImageResource method of our CaptionedImageView. That method simply sets the reference to our drawable and sets the drawable for the image view and then moves on to the blur code. But look a little closer. The drawable reference is being created by inflating the drawable via our resources. The ImageView is then having its image set via the resource ID, which causes it to be inflated again. By simply changing that line to instead call setImageDrawable and pass in mDrawable, we eliminate that second instance of decodeBitmap, which was taking around 60 milliseconds.

Maybe you caught this back in Chapter 8, “Applying the Design,” but this is the type of mistake that’s very easy to make and yet might not be caught. Having a code review process helps increase the chance that this will be caught, but there are still times when it will slip by or you might be working on your own without anyone to review your code. By making use of Android’s performance tracking tools, you can catch issues like this, and you will eventually start to get used to keeping your eyes out for these types of problems.

You can run the app with the change and immediately feel the difference, but it’s still not smooth, so let’s make better use of Systrace. We are reasonably sure that the slowdown is in this area, so let’s update the setImageResource method so that the first line beings a new trace section and that section is ended in the last line of the method. You can call the sections anything you want, but you can consider a prefix if you’re adding a lot of related sections, so something like “BLUR — setImageResource” tells you that this section is part of the overall blurring process and is specifically the setImageResource call. Diving into the updateBlur method, there are a lot of different places that might be the cause of slowdown. This is a case where intuition and experience will help you decide, but you can’t go wrong with extra logging.

Anywhere that you create or manipulate a bitmap is a good place to track. For instance, the two lines that create the portionToBlur and blurredBitmap objects can be wrapped with TraceCompat calls (that is, put a call to beginSection before those objects are created and a call to endSection after). Wrapping the full RenderScript section is also a good idea. You can even add some sections within the RenderScript portion of the code to better understand what is taking time there. Listing 10.1 shows an example of the setImageResource and updateBlur methods.

Listing 10.1 An Example of Methods with Systrace Logging Added

public void setImageResource(@DrawableRes int drawableResourceId) {
    TraceCompat.beginSection("BLUR — setImageResource");
    mDrawable = getResources().getDrawable(drawableResourceId);
    mImageView.setImageDrawable(mDrawable);
    updateBlur();
    TraceCompat.endSection();
}

private void updateBlur() {
    if (!(mDrawable instanceof BitmapDrawable)) {
        return;
    }
    final int textViewHeight = mTextView.getHeight();
    if (textViewHeight == 0) {
        return;
    }

    // Determine the size of the TextView compared to the height of the ImageView
    final float ratio = (float) textViewHeight / mImageView.getHeight();

    // Get the Bitmap
    final BitmapDrawable bitmapDrawable = (BitmapDrawable) mDrawable;
    final Bitmap originalBitmap = bitmapDrawable.getBitmap();

    // Calculate the height as a ratio of the Bitmap
    int height = (int) (ratio * originalBitmap.getHeight());

    // The y position is the number of pixels height represents from the bottom of the Bitmap
    final int y = originalBitmap.getHeight() — height;

    TraceCompat.beginSection("BLUR — createBitmaps");
    final Bitmap portionToBlur = Bitmap.createBitmap(originalBitmap, 0, y, originalBitmap.getWidth(), height);
    final Bitmap blurredBitmap = portionToBlur.copy(Bitmap.Config.ARGB_8888, true);
    TraceCompat.endSection();

    // Use RenderScript to blur the pixels
    TraceCompat.beginSection("BLUR — RenderScript");
    RenderScript rs = RenderScript.create(getContext());
    ScriptIntrinsicBlur theIntrinsic = ScriptIntrinsicBlur.create(rs, Element.U8_4(rs));
    TraceCompat.beginSection("BLUR — RenderScript Allocation");
    Allocation tmpIn = Allocation.createFromBitmap(rs, portionToBlur);
    // Fix internal trace that isn't ended
    TraceCompat.endSection();
    Allocation tmpOut = Allocation.createFromBitmap(rs, blurredBitmap);
    // Fix internal trace that isn't ended
    TraceCompat.endSection();
    TraceCompat.endSection();
    theIntrinsic.setRadius(25f);
    theIntrinsic.setInput(tmpIn);
    TraceCompat.beginSection("BLUR — RenderScript forEach");
    theIntrinsic.forEach(tmpOut);
    TraceCompat.endSection();
    TraceCompat.beginSection("BLUR — RenderScript copyTo");
    tmpOut.copyTo(blurredBitmap);
    TraceCompat.endSection();
    new Canvas(blurredBitmap).drawColor(mScrimColor);
    TraceCompat.endSection();

    // Create the new bitmap using the old plus the blurred portion and display it
    TraceCompat.beginSection("BLUR — Finalize image");
    final Bitmap newBitmap = originalBitmap.copy(Bitmap.Config.ARGB_8888, true);
    final Canvas canvas = new Canvas(newBitmap);
    canvas.drawBitmap(blurredBitmap, 0, y, new Paint());
    mImageView.setImageBitmap(newBitmap);
    TraceCompat.endSection();
}

Running the app and using Systrace again, we can see that a particular instance of the obtainView call is now taking 90 milliseconds with the decodeBitmap portion roughly two-thirds of that. The RenderScript portion of our code is the majority of the rest of the time with almost half of the RenderScript time coming from the copyTo call. Let’s start with the image loading portion, because that’s the larger part.

  • + Share This
  • 🔖 Save To Your Account