I made a build visualizer to understand Bun’s compile times

I built buildprof
(Github), an open-source tracing
tool that shows where the time goes when you compile software on Linux. Here’s a
realtime video of it profiling a clean build of ripgrep:

Sometimes, builds are slow because there is simply a lot of code to compile. But
more often than not, there are fixable problems: poor parallelism, repeated
work, dependency downloads or a huge compiler/linker invocation. buildprof makes
all of this clearly visible, so you can see what’s worth investigating and
optimizing.

You run it by putting buildprof -- in front of any build command you already
use:

buildprof -- make -j16
buildprof -- cargo build
buildprof -- ninja -C out/target
buildprof -- just build
buildprof -- ./dev/custom-build-script.sh

buildprof records every process your build command launches, including their
subprocesses (and their subprocesses…), and lays them out on one timeline.
Time moves from left to right, bar width shows duration, and child processes
appear beneath whatever launched them.

I made buildprof because
this tweet from Jarred
Sumner, chief architect of the Bun JavaScript runtime, was living rent free in
my head:

Specifically, the claim that Bun’s new Rust build was >5× faster on Linux than
its old Zig build really bothered me. In my experience, Zig projects had usually
compiled much faster than Rust projects of similar complexity. That intuition
was enough to make me feel there was a mystery to solve.

This was further compounded by another important, yet easily missed, detail in
the tweet: the Zig build used Full LTO, while the Rust build used ThinLTO.

Compilers normally optimize separate compilation units largely in
isolation. ^{Link-time optimization (LTO) lets them optimize
across those boundaries. Full LTO brings those units together into one large
optimization job, while ThinLTO preserves more separation so much of the work
can run in parallel.}

From past experience, this difference can have an enormous effect on build
time. The tweet mentioned it in passing, but I wondered how much of the headline
improvement it explained.

I started by trying to reproduce the numbers.

The numbers reproduced. But now what?#

I checked out
Bun 1.3.14 and
Bun 1.4.0 and wrote
some scripts
to replay their Linux x64 CI builds on a 6-core, 12-thread Linux VM. The scripts
preserved the build steps and their dependencies, running everything on one
machine.

My timings were in the same ballpark as Jarred’s:

OK, so the gap showed up on my machine too. But a lot had changed between the
two measurements besides the language; so what was actually responsible? Was it
the Zig compiler that was taking all that extra time? Or maybe it was the Full
LTO link? Or perhaps there was something else in Bun’s build I hadn’t even
thought to look at?

This is where my profiling and developer-tools brain kicked in. Usually, when
I’m trying to understand why something is slow, I want a trace: what happened,
when it happened and how long it took. It would be really cool to have that for
these builds, to put them on a timeline and see where their time actually went.

But a build involves a lot of different tools, each with its own idea of what’s
happening. What could I record that would let me see across all of them?

Builds are process trees#

When you type cargo build or zig build, it feels like you are running one
program. The build system works out what needs to be rebuilt, the ordering
between those pieces and what can run in parallel. But generally, it does not
perform all that work itself; it launches compilers, code generators, archivers,
linkers and arbitrary scripts. Which can launch more programs which launch some
more…

Different build systems describe that work in different ways. Cargo sees crates,
Ninja sees build edges and CMake generates instructions for another build
system. From the operating system’s point of view, however, they (mostly) look
like processes launching other processes.

A Rust build, for example, might contain a chain like this:

cargo
└── rustc
    └── cc
        └── collect2
            └── ld.lld

If we record when each subprocess starts and ends, we can lay them out on a
timeline. Here’s what that chain looks like in buildprof:

There are also several nice properties to visualizing a build at this layer:

1. It’s build-system agnostic: Cargo, Ninja, Zig, Make and most other build
   systems do much of their work by spawning processes, so we do not need to
   write a special integration for each one.
2. It naturally includes custom scripts: This includes both scripts above
   the build system (repository setup, dependency fetching) and scripts
   underneath it (code generators, asset processors).
3. We can follow the files between build steps: recording which files each
   process reads and writes lets us see which steps produce the inputs for
   others. This even works across build systems!

This gave me a starting point for buildprof: record the process tree, then turn
it into a timeline I could explore. There are plenty more details to get into,
which I will do later. But once I had that working, I could finally go back to
my initial question: what was Bun doing for those twenty-four minutes?

Pointing it at Bun#

Why was the Zig CI build so much slower?#

I started by recording the Zig-era CI build with buildprof, using the
same scripts as before:

Explore in buildprof

Right away we can see a huge problem: the ld.lld linker invocation dominates
the build time. It ran alone at the very end for over sixteen minutes, about
two-thirds of the entire build. What the heck was it doing for all that time?

Clicking on the linker shows its command line, which buildprof captures
automatically:

There’s Full LTO, just as Jarred said. Given how long the link was taking, it
was now my main suspect.

But the process tree alone couldn’t tell me whether LTO was actually responsible
for those sixteen minutes. Thankfully, LLD records its own internal timing
events, and buildprof can include them when you use --compiler-traces.

I
recorded the final link again,
this time with --compiler-traces enabled:

Explore in buildprof

Now we can see that LTO is where almost all the time goes. The linker is
running compiler passes over the program, not just combining already-compiled
files. The OptModule bar alone takes just over ten minutes and includes the
passes which generate machine code.

How did the Rust CI build differ?#

With so much of the Zig build spent in LTO, I wanted to see how much time the
Rust build spent linking. I recorded that build too:

Explore in buildprof

Just 2m24s. And this time, as expected, the linker command contains
-plugin-opt=thinlto:

Both builds were doing LTO, but with different settings and very different link
times. What if I kept Bun’s Zig code and changed Full LTO to ThinLTO? How much
of the gap would that close?

Trying ThinLTO#

I
switched Zig Bun’s build flags to ThinLTO
and recorded another clean build, along with a fresh Full-LTO build for
comparison:

Explore in buildprof: Full LTO · partial ThinLTO

The link got 3m40s faster in this pair of recordings, but it was still taking
nearly thirteen minutes. Why was linking still so expensive?

Looking back at the compiler trace, a lot of the work was on functions with
JSC in their names. That’s JavaScriptCore, the engine Bun uses to execute
JavaScript. The linker was spending time compiling the JavaScript engine
too.

Clicking on the linker invocation showed the
WebKit
libraries among its inputs, including libJavaScriptCore.a:

Following those inputs back through the build, I found that Bun wasn’t compiling
these libraries itself. It was downloading them from a separate WebKit build.
And when I checked
that build’s flags,
there it was again: -flto=full. The Rust build used a newer WebKit revision
whose
build recipe selected ThinLTO.

Even though I had changed how Bun compiled its own code, those downloaded
libraries still contained Full-LTO inputs and so the linker still had to
optimize that code and turn it into machine code. To change that, I would have
to rebuild WebKit too.

Rebuilding WebKit#

I checked out the historical WebKit revision and rebuilt it and its ICU
dependencies with compatible ThinLTO settings. Then I replaced the downloaded
libraries with the ones I had built, keeping the ThinLTO changes to Bun.

Here are the recorded builds:

The link now took 7m22s. Still slower than the Rust build, but enough of an
improvement that I wanted to look beyond the linker.

What about the rest of the build?#

The build still took fifteen minutes, and nearly eight of those passed before
the linker even started. What was it waiting for? I went back to the original CI
trace to follow the inputs from Bun’s own code.

buildprof also records which files each process reads and writes. If a process
reads a file another wrote, it links the two together under the hood. Turning on
“Show on timeline” draws those links as arrows. Here, the linker reads
libbun-profile.a from the C++ compilation and bun-zig.o from Zig. Both
arrive through copy steps; following those back takes us to the processes which
produced them:

The C++ side of the compilation finished first. The linker was waiting for
bun-zig.o, so it could not begin until the Zig branch had finished too.

It was at this point I went back to the Rust build and compared against how it
worked, and the main reason the Rust build was faster became obvious: Bun has
been split into >90 crates, while in Zig it was all trying to compile as a
single Zig module!

This meant that the Zig build cannot parallelise the same way Rust can. I also
suspect, though I did not prove this, that it explains the slow linking: the
linker has to optimize one huge ThinLTO bitcode module instead of the same work
spread across crates.

It was at this point I had to stop: to go any further, I would have to split up
the Zig module myself, and given that this code is all obsolete anyway, I didn’t
think it was worth doing that.

Summarizing:

• The huge outlier in the initial Zig build vs the Rust build was the massive
  linker step which ran alone at the end of the build.
• Changing the LTO settings for just Bun was not sufficient as WebKit, a
  significant part of the build, still used Full LTO.
• Once I had done this, the Zig build dropped from twenty-four minutes to
  fifteen.
• Even after this, linking still took 7 minutes and the whole build 15 minutes.
• The overwhelming difference which remained was structural: Rust spreads
  compilation across >90 crates while the Zig build funnelled everything through
  a single module.

And fwiw, the traces had also turned up a few things I couldn’t resist poking
at…

Other things hiding in the build#

A build can contain almost anything#

In the middle of Bun’s CI build, I found commands asking the public internet for
the machine’s IP address, inspecting running Docker containers and reading the
latest Git commit message.

These take well under a second altogether. Nothing to optimize but I just wasn’t
expecting to find them in a build trace.

A cold dependency fetch#

The builds above reused downloaded dependencies, so I also
recorded a fresh WebKit fetch.
Downloading and extracting the archive took about twenty seconds. For the first
twelve, all we see is Node running. Then it launches tar and gzip, and we
can see the extraction separately.

Looking inside one C++ compilation#

Earlier, we followed the linker’s inputs back to Bun’s C++ compilation. We can
look inside those compiler invocations too. I picked one of the last files to
finish, ZigGeneratedClasses.cpp, and
replayed its Ninja command
with --compiler-traces. For Clang, buildprof enables -ftime-trace and adds
its internal timings to the process timeline.

The replay took about twelve seconds, split almost evenly between Clang’s
frontend and backend. Zooming in further, we see ModuleInlinerWrapperPass, one
of the phases of Clang, accounts for over four seconds of the backend’s work.

How buildprof works under the hood#

The recording side of buildprof uses ptrace, the same Linux interface used by
debuggers. I did consider both eBPF and ftrace, but ptrace is just straight up
perfect for exactly this type of problem; eBPF tracing means CAP_BPF and
CAP_PERFMON permissions and hooking into potentially unstable
tracepoints/kernel functions. While with ftrace, I’d have to juggle tracing
instances to avoid interfering with other users, and getting the filters perfect
for just the build process and all its descendants is
cumbersome.

With ptrace, I can launch the build and follow its children directly. Its
built-in events tell buildprof when processes fork, exec a new program or exit.
And for filesystem activity, buildprof uses a seccomp filter to intercept only
the calls it needs.

How much buildprof costs is almost entirely down to how many files the build
opens. For ripgrep, recording barely changed the build time. Redis opened files
much more often, and recording added about five seconds:

If that overhead gets in the way, you can turn off filesystem tracing with
--no-file-events and keep the process timeline.

I work on Perfetto, so it was a natural
starting point for the UI; buildprof’s UI is a soft fork of the Perfetto UI. I
could have just opened the recordings on
ui.perfetto.dev, but I wanted control over how the
process tree was laid out, which details appeared when you clicked a command,
and things like those on-demand arrows between file producers and consumers.

Fortunately, we’ve spent the last several years working on making the Perfetto
UI extensible through
plugins. Most of
buildprof’s UI is reusing that infrastructure. Perfetto handles the hard stuff
(parsing traces, querying events, rendering the timeline and managing
workspaces) and I get to focus on what makes those things useful for builds.

I plan on going into a lot more detail about the recorder and UI in a separate
technical post. Subscribe if you’d like to
be notified when it comes out! 🙂

Did I need to build something new?#

These days it’s very easy to make a tool just because you can. But that wasn’t
the case here; before building buildprof, I looked long and hard for an existing
tool that could give me this view.

I started with ninjatracing, which I’ve
used many times. It turns Ninja’s build log into a timeline showing what ran and
how much ran in parallel.

Here’s the Ninja log from the Zig-era build.

But Ninja only sees part of Bun’s build. The scripts which invoke it are missing
from its log, and commands it runs appear as single blocks even when they launch
whole trees of subprocesses.

There were several other tools, each covering different parts of the problem:

• Cargo timings works
  well for Cargo-managed builds, but cannot break down arbitrary work inside
  build.rs or see wrapper scripts above Cargo. In Bun, Cargo is only part of
  the build:
  the report I captured
  covered 1m51s of a 5m40s CI build.
• Clang’s -ftime-trace
  gave us the detail inside a compiler invocation, but cannot show what the rest
  of the build is doing while
  Zig’s Tracy integration
  goes deeper still and is intended more for understanding the compiler itself.
• strace and
  tracexec can follow arbitrary processes
  through fork and exec, but show general process events rather than a
  build-oriented timeline.

What the Fork
(via) came closest: it follows
processes across build systems and presents a build-specific view. But as far as
I could tell, it still appears to be in private beta and there don’t seem to be
any plans to make it open source.

What’s next for buildprof#

buildprof already does what I wanted it to do, and I plan to keep working on it
as I use it on my own builds. But there are a few things I’d like to improve.

Recording overhead is one; the Redis measurements showed there’s room to improve
filesystem tracing, especially for builds which open lots of files. I’d also
like to support macOS
where I do some of my work and maybe
Windows if there’s
interest.

There are also more build systems and toolchains I’d like to test, including
npm, Gradle and Bazel. Computing critical paths would also be a big improvement:
we followed dependencies by hand in this post, but buildprof could help identify
the chain of work holding up the build and automatically annotate it.

I’ll probably tackle these as and when I need them. But if you try buildprof and
there’s something you wish it could do, I’d be interested to
hear about it. What people
find useful will help me decide where to spend more time.

Conclusion#

I managed to satiate my curiosity, though I ended up spending rather more time
on this than I expected. Along the way I built a tool I now want to have around
whenever a build is taking too long.

I know I’ll come back to buildprof the next time a slow build annoys me. If you
have one of those builds too,
give it a try. I’d love
to hear what you find!