I made a build profiler to understand Bun's compile times

I made a build profiler to understand Bun's compile times 图片 1

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:

Linux x64 build Zig era Rust era
Bun’s reported CI median 30m06s 5m37s
My single-machine CI-profile replay 24m24s 5m40s

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:

Zig-era build Whole build Final linker
Original Full LTO 24m24s 16m35s
Bun ThinLTO; original WebKit archives 20m20s 12m55s
Bun ThinLTO; rebuilt ThinLTO WebKit and ICU 15m11s 7m22s

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:

Build Untraced Processes only Processes + files
ripgrep / Cargo 12.27s 12.30s 12.43s
Redis / Make 26.78s 27.04s 31.89s

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. 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!


  1. In C and C++, a compilation unit is usually a source file together with its included headers. Rust compiles crates, which can be split into multiple code-generation units. Zig normally compiles a program’s Zig sources together as a single compilation unit. Bun’s Zig compiler fork supports splitting that into multiple LLVM modules, but its CI build explicitly selected one when LTO was enabled.
  2. The Zig-era CI build ran its C++ and Zig compilation stages on separate Buildkite machines and passed their outputs to a final linking stage. My script ran those stages concurrently on one machine, waited for both outputs, copied them locally instead of transferring them over the network, then linked them. This should preserve the dependency graph, but due to the hardware differences and running both stages on one machine, resource contention would obviously be quite different. Also note that my timings are individual runs (albeit ones which were quite stable) while Bun’s reported figures are medians.
  3. A process can do substantial work internally, including running multiple threads, without launching anything else. The process timeline won’t show that parallelism. To see inside a process, we need tracing from the program itself, as Clang and LLD provide in the examples below.
  4. LLVM emits OptModule from its legacy pass manager, which LLD uses for code generation. The inlining and other IR optimization passes can appear before it, so this bar is not the total time spent optimizing a module.
  5. In the earlier Full-LTO linker replay, 26,825 OptFunction events with JSC symbols total about 209s. This is summed event time, not a measurement of JavaScriptCore’s entire contribution to the link. One example event takes 2.94s; its symbol demangles to JSC::JITThunks::initialize(JSC::VM&).
  6. Recording script. These timings are just for building Bun with the libraries already available; the WebKit and ICU rebuild happened beforehand and isn’t included. Of course, I could point buildprof at that build too, but that’s another rabbit hole… I did not rebuild a matching Full-LTO WebKit archive as a control, so I cannot attribute every second saved to the LTO setting alone.
  7. buildprof currently supports compiler traces from Clang, LLD and nightly Rust.
  8. eBPF tracing uses capabilities such as CAP_BPF and CAP_PERFMON, as described in the kernel’s capability definitions. ftrace provides separate tracing instances and PID filters, but these still need configuring and access to tracefs. ptrace also depends on the host’s security settings; containers may need additional permissions to allow tracing child processes.
  9. Medians of five clean builds per mode on the same VM, with six build jobs. Measurement script.
添加评论
点赞收藏
点踩分享查看原文
评论
?
参与讨论