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
$ 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
$ 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:
- 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.
- 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.
- 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.
- 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.