Build, y u go slow?

When a build is taking too long, it can be very helpful to know what it’s doing. Bazel has built-in tooling that lets you visualize what each thread is doing at any given moment of a build and which build steps are slowing down your overall build.

To try out Bazel’s profiling tools, build your favorite (or, rather, least-favorite) target with the --profile option:

$ bazel build --profile=myprofile.out //snail:slow-lib

This will write the profile to a file called myprofile.out in the current directory. Once your build finishes, you can take a look at this file, but it’s not really designed to be read by humans. Instead, plug it into Bazel’s analyze-profile command:

$ bazel analyze-profile --html myprofile.out

Now you wait for Bazel to analyze the profile info and enjoy this picture of a snail I saw walking Domino the other day (penny included for scale):

(After taking this photo, I moved the snail onto the grass, since I’m pretty sure it was not delighted to be in the middle of a NYC sidewalk.)

Ding, analysis is probably done. Now you can open up myprofile.out.html and see your build, broken down into hundreds or thousands of individual steps. A screenshot of the output:

I uploaded the HTML page so you can see the whole thing here and play with it (it will open in a new tab).

I used the //android target from the example app for the profile above, since it’s a little more meaty than a toy example.

The chart shows what all 200 build threads were doing during the build at any given time (one thread per row). The build is divided into several “phases” which are shown as different colored columns on the chart:

1. The first 1.5 seconds (darkish grey) were spent initializing the build command, which means it was just parsing options and setting up the cache.
2. The next ~1 second (green) was the loading phase, where Bazel figures out which packages it will need, downloads external dependencies, and finds and parses BUILD files.
3. The next ~100ms (sliver of light grey) was the analyze dependencies phase, where Bazel figured out which dependencies were cached and clean and so did not need to be rebuilt.
4. Finally, Bazel moved into the build phase (pink background), actually building all of the things that needed to be built.

There are several other phases that you can see on the legend, but they are, for the most part, too short to even be visible on the chart.

Below the chart, there’s a section for “Execution phase.” “Execution” can be a little confusing in this context: it’s referring to executing the build, not running your program. The execution phase maps to the pink phase in the chart above. In this section is a sub-section called “Critical path, ” which breaks down what your build was waiting on:

Critical path (13.339 s):
    Id        Time Percentage   Description
  6722     48.1 ms    0.36%   Zipaligning apk
  6721      344 ms    2.58%   Generating signed apk
  6720      540 ms    4.05%   Converting bazel-out/local_darwin-fastbuild/bin/android/android_deploy.jar to dex format
  6719      230 ms    1.73%   Building deploy jar android/android_deploy.jar
  6718     1.051 s    7.88%   Building android/libandroid.jar (0 files)
  6717     15.7 ms    0.12%   Extracting interface //android activities
  6716     1.744 s   13.07%   Building android/libactivities.jar (1 files)
  6715      785 ms    5.89%   Processing resources
  6712     3.737 s   28.01%   Building external/default_android_tools/src/tools/android/java/com/google/devtools/build/android/libandroid_builder_lib.jar (17 files) [for host]
  6711     4.843 s   36.30%   Writing file external/default_android_tools/src/tools/android/java/com/google/devtools/build/android/libandroid_builder_lib.jar-2.params [for host]
           1.73 ms    0.01%   [2 middleman actions]

As you can see, the build was “blocked” for more than 8 seconds building libandroid_builder_lib.jar and its params file. Luckily, these files shouldn’t change between builds (unless you update your Android SDK, which shouldn’t happen between every build). If I make a change to libactivities.jar (the actual meat of the program) and rebuild, I get:

$ bazel build --profile profile2 //android
INFO: Writing profile data to '/Users/kchodorow/gitroot/examples/tutorial/profile2'
INFO: Found 1 target...
INFO: From Generating unsigned apk:

THIS TOOL IS DEPRECATED. See --help for more information.

INFO: From Generating signed apk:

THIS TOOL IS DEPRECATED. See --help for more information.

Target //android:android up-to-date:
  bazel-bin/android/android_deploy.jar
  bazel-bin/android/android_unsigned.apk
  bazel-bin/android/android.apk
INFO: Elapsed time: 4.545s, Critical Path: 2.72s

Here is the new profile page for this incremental build.

Note that the critical path is only 2.718 seconds now, not 13.339! If we look at the profile, we can see that the new critical path is much more svelte:

Critical path (2.718 s):
    Id        Time Percentage   Description
   543     52.3 ms    1.92%   Zipaligning apk
   542      342 ms   12.59%   Generating signed apk
   541      577 ms   21.22%   Converting bazel-out/local_darwin-fastbuild/bin/android/android_deploy.jar to dex format
   540      245 ms    9.00%   Building deploy jar android/android_deploy.jar
   539     1.502 s   55.26%   Building android/libactivities.jar (1 files)

Now building libactivities.jar is the most heavyweight operation on the critical path, so we could tackle that by perhaps breaking it into separate libraries that don’t all have to be recompiled every time something changes.

The profiles Bazel generates can be… dense… so feel free to ask on the mailing list if you need any help interpreting them. Also, if you’re interested in more on the subject, check out the documentation on profiling.