Bunのコンパイル時間を理解するためにビルドビジュアライザーを作成しました

Bunのコンパイル時間を理解するためにビルドビジュアライザーを作成しました

私はbuildprof（Github）を構築しました。これは、Linuxでソフトウェアをコンパイルする際、時間がどこに費やされているかを示すオープンソースのトレーシングツールです。ripgrepのクリーンビルドをプロファイルするリアルタイムビデオをご覧ください。

［動画: buildprofのデモを見る］

ビルドが遅くなるのは、単にコンパイルするコード量が膨大であるためという場合もあります。しかし、多くの場合、修正可能な問題が存在します。例えば、並列処理の不足、重複作業、依存関係のダウンロード、あるいは巨大なコンパイラ/リンカの呼び出しなどです。buildprofはこれらの問題をすべて明確に可視化するため、調査や最適化に値する箇所を特定できます。

使い方は、既存のビルドコマンドの前に buildprof -- を付けるだけです。

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

buildprofは、ビルドコマンドが起動するすべてのプロセス、およびそのサブプロセス（さらにそのサブプロセス…）を記録し、1つのタイムライン上に配置します。時間は左から右へ流れ、バーの幅は期間を示し、子プロセスはそれを起動したものの下に表示されます。

［画像: ripgrepのビルド：Cargoがビルド全体を占め、rustcの呼び出しがクレートを並列コンパイルし、最終的なrustcの呼び出しがリンカチェーンを起動する］

私がbuildprofを作成したのは、Bun JavaScriptランタイムのチーフアーキテクトであるJarred Sumner氏のこのツイートが頭から離れなかったからです。

［画像: Bun 1.3.14のLinuxでの中央値ビルド時間が30分6秒、Bun 1.4.0では5分37秒であることを示すJarred Sumner氏の比較］

特に、Bunの新しいRustビルドがLinuxで古いZigビルドよりも5倍以上高速であるという主張は、私を悩ませました。私の経験では、Zigプロジェクトは通常、同程度の複雑さのRustプロジェクトよりもはるかに高速にコンパイルされていました。その直感が、解決すべき謎があると感じさせるには十分でした。

さらに、ツイートにはもう一つ重要でありながら見落とされがちな詳細がありました。それは、ZigビルドがFull LTOを使用していたのに対し、RustビルドはThinLTOを使用していたことです。

通常、コンパイラは個別のコンパイル単位をほぼ独立して最適化します。[1] リンク時最適化（LTO）により、それらの境界を越えて最適化できます。Full LTOはそれらの単位を1つの大きな最適化ジョブにまとめますが、ThinLTOはより多くの分離を維持するため、作業の多くを並列実行できます。

過去の経験から、この違いはビルド時間に壊滅的な影響を与える可能性があります。ツイートでは軽く触れられていましたが、見出しの改善のどれだけがこれを説明しているのか疑問に思いました。

私はまず、その数値を再現しようとしました。

数値は再現できた。しかし、次は何を？#

Bun 1.3.14とBun 1.4.0をチェックアウトし、それらのLinux x64 CIビルドを6コア12スレッドのLinux VMで再現するためのスクリプトを作成しました。スクリプトはビルドステップとその依存関係を維持し、すべてを1台のマシンで実行しました。[2]

私の計測時間はJarred氏のものとほぼ同じ範囲でした。

OK、私のマシンでもギャップが現れました。しかし、2つの測定の間には言語以外にも多くの変化がありました。では、実際に何が原因だったのでしょうか？あの余分な時間をすべて費やしていたのはZigコンパイラだったのでしょうか？それともFull LTOリンクだったのでしょうか？あるいは、私がまだ考えてもいなかったBunのビルドに何か別の要因があったのでしょうか？

ここで私のプロファイリングと開発者ツールの知識が役立ちました。通常、何かが遅い理由を理解しようとするとき、私はトレースを必要とします。つまり、何が、いつ、どれだけ時間がかかったかを知りたいのです。これらのビルドでそれを行うことができれば、タイムライン上に配置して、実際にはどこに時間が費やされたのかを見ることができます。

しかし、ビルドには多くの異なるツールが含まれており、それぞれが何が起こっているかについての独自の考えを持っています。それらすべてを横断して見ることができるように、何を記録できるでしょうか？

ビルドはプロセスツリーである#

cargo build や zig build と入力すると、1つのプログラムを実行しているように感じます。ビルドシステムは、何を再構築する必要があるか、それらのピース間の順序、そして何が並列実行できるかを判断します。しかし、一般的に、ビルドシステム自体がその作業のすべてを実行するわけではありません。コンパイラ、コードジェネレータ、アーカイバ、リンカ、そして任意のスクリプトを起動します。それらはさらにプログラムを起動し、さらにプログラムを起動します…

異なるビルドシステムは、その作業を異なる方法で記述します。Cargoはクレートを見、Ninjaはビルドエッジを見、CMakeは別のビルドシステムのための指示を生成します。しかし、オペレーティングシステムの観点からは、それらは（ほとんどの場合）プロセスが他のプロセスを起動しているように見えます。[3]

例えば、Rustのビルドは次のようなチェーンを含む場合があります。

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

各サブプロセスがいつ開始し、終了したかを記録すれば、それをタイムライン上に配置できます。buildprofでのそのチェーンの様子は次のとおりです。

［画像: ripgrepビルドの最終リンク。cargoがrustcを起動し、次にcc、collect2、ld.lldをその下に起動する様子を示す］

このレイヤーでビルドを可視化することには、いくつかの良い特性があります。

1. ビルドシステムに依存しない: Cargo、Ninja、Zig、Make、その他のほとんどのビルドシステムは、プロセスの起動によって多くの作業を行うため、それぞれに特別な統合を記述する必要はありません。
2. カスタムスクリプトを自然に含める: これには、ビルドシステムの上位（リポジトリセットアップ、依存関係取得）および下位（コードジェネレータ、アセットプロセッサ）のスクリプトが含まれます。
3. ビルドステップ間のファイルを追跡できる: 各プロセスが読み書きするファイルを記録することで、どのステップが他のステップの入力を作成したかを確認できます。これはビルドシステム間でも機能します！

これがbuildprofの出発点となりました。プロセスツリーを記録し、それを探索可能なタイムラインに変換します。さらに詳細な点は後で説明しますが、それが機能するようになれば、最初の質問に戻ることができました。Bunはあの24分間で何をしていたのでしょうか？

Bunを対象にする#

ZigのCIビルドがこれほど遅かったのはなぜか？#

私はbuildprofを使用して、以前と同じスクリプトで、Zig時代のCIビルドを記録することから始めました。

［画像: 完全なZig時代のCIビルド］

buildprofで探索する

すぐに大きな問題が見つかりました。ld.lld リンカの呼び出しがビルド時間を支配していました。ビルドの最後で16分以上単独で実行され、ビルド全体の約3分の2を占めていました。一体あれほど長い時間、何をやっていたのでしょうか？

リンカをクリックすると、buildprofが自動的にキャプチャするコマンドラインが表示されます。

［画像: 選択されたZig時代のリンカとそのFull LTOフラグ］

Jarred氏が言っていたように、Full LTOがありました。リンクにこれほど時間がかかっていたことを考えると、それが私の主な容疑者となりました。

しかし、プロセスツリーだけでは、LTOが実際にそれらの16分間の原因であったかどうかはわかりませんでした。幸いなことに、LLDは独自の内部タイミングイベントを記録しており、--compiler-traces を使用するとbuildprofはそれらを含めることができます。

私は最終リンクを再度記録しました。今回は --compiler-traces を有効にしていました。

［画像: LLDの内部フェーズ］

buildprofで探索する

これで、ほとんどすべての時間がLTOに費やされていることがわかります。リンカは、ファイルを結合するだけでなく、プログラム全体にコンパイラパスを実行していました。OptModule バーだけで10分以上かかり、マシンコードを生成するパスが含まれています。[4]

RustのCIビルドはどう異なったか？#

Zigビルドの大部分がLTOに費やされていたため、Rustビルドがリンクにどれだけの時間を費やしたかを確認したかったのです。そのビルドも記録しました。

［画像: 完全なRust時代のCIビルド］

buildprofで探索する

わずか2分24秒でした。そしてこの時、予想通り、リンカコマンドには -plugin-opt=thinlto が含まれていました。

［画像: ThinLTOが有効になっているRustリンカの呼び出し］

両方のビルドでLTOが行われていましたが、設定が異なり、リンク時間も大きく異なりました。BunのZigコードをそのままにして、Full LTOをThinLTOに変更したらどうなるでしょうか？そのギャップのどれだけを埋めることができるでしょうか？

ThinLTOを試す#

私はZig BunのビルドフラグをThinLTOに変更し、比較のために別のクリーンビルドと、新しいFull LTOビルドを記録しました。

［画像: マッチしたFull LTOビルドと部分的なThin LTO実験］

buildprofで探索する: Full LTO · 部分的なThin LTO

この一連の記録ではリンクは3分40秒速くなりましたが、それでも13分近くかかっていました。なぜリンクがまだそれほど高コストだったのでしょうか？

コンパイラトレースを振り返ると、作業の多くは JSC という名前の関数にかかっていました。これはBunがJavaScriptを実行するために使用するエンジン、JavaScriptCoreです。リンカはJavaScriptエンジンのコンパイルにも時間を費やしていました。[5]

リンカの呼び出しをクリックすると、入力の中にWebKitライブラリ、特にlibJavaScriptCore.aが含まれていることがわかりました。

［画像: リンカコマンドはThinLTOが有効になっているが、libJavaScriptCore.aを含むWebKitのライブラリも含まれている］

これらの入力をビルド全体で追跡したところ、Bunはこれらのライブラリを自分でコンパイルしていませんでした。別のWebKitビルドからダウンロードしていました。そして、そのビルドのフラグを確認したところ、そこにも -flto=full がありました。Rustビルドは、ビルドレシピでThinLTOを選択した新しいWebKitリビジョンを使用していました。

Bun自身のコードのコンパイル方法を変更したにもかかわらず、ダウンロードされたライブラリにはFull LTOの入力が含まれていたため、リンカは依然としてそのコードを最適化し、マシンコードに変換する必要がありました。それを変更するには、WebKitも再ビルドする必要がありました。

WebKitの再ビルド#

履歴上のWebKitリビジョンをチェックアウトし、そのICU依存関係とともに互換性のあるThinLTO設定で再ビルドしました。次に、ダウンロードしたライブラリをビルドしたものに置き換え、BunのThinLTO変更を維持しました。

記録されたビルドは次のとおりです。[6]

リンクは7分22秒になりました。Rustビルドよりは遅いですが、リンカのさらに奥を調べたいと思わせるほどの改善でした。

ビルドの残りはどうだったか？#

ビルドはまだ15分かかり、そのうち約8分はリンカが開始する前に経過しました。何のために待っていたのでしょうか？Bun自身のコードからの入力を追跡するために、元のCIトレースに戻りました。

buildprofは、各プロセスが読み書きするファイルも記録します。あるプロセスが別のプロセスが書き込んだファイルを読み込む場合、それは内部的にそれらをリンクします。「タイムラインに表示」をオンにすると、それらのリンクが矢印として描画されます。ここでは、リンカはC++コンパイルからのlibbun-profile.aとZigからのbun-zig.oを読み込みます。どちらもコピー手順を経て到着します。それらを遡って追跡すると、それらを生成したプロセスにたどり着きます。

［画像: リンカの依存関係矢印をコピー手順を経てC++およびZigのプロデューサーにたどる。プロデューサーパネルは同じ時間スケールを使用。C++が先に完了する］

C++側のコンパイルが先に完了しました。リンカはbun-zig.oを待っていたため、Zigブランチが完了するまで開始できませんでした。

この時点で、Rustビルドに戻って比較したところ、Rustビルドが速かった主な理由が明らかになりました。Bunは90以上のクレートに分割されていますが、Zigではすべてを単一のZigモジュールとしてコンパイルしようとしていました！

［画像: CargoがBunのクレート全体にわたる名前付きrustcプロセスに展開される様子。何も起動しない単一のzig build-objプロセスと並べて表示］

これは、ZigビルドがRustと同じようには並列化できないことを意味します。また、証明はしませんでしたが、これが遅いリンクの原因である可能性も疑っています。リンカは、クレート全体に分散された同じ作業ではなく、1つの巨大なThinLTOビットコードモジュールを最適化する必要があるのです。

この時点で私は停止せざるを得ませんでした。さらに進むには、自分でZigモジュールを分割する必要がありましたが、このコードはすべて廃止されていることを考えると、それを行う価値はないと思いました。

要約:

• 初期のZigビルドとRustビルドの間の巨大な外れ値は、ビルドの最後に単独で実行された大規模なリンカステップでした。
• BunのみのLTO設定を変更しても十分ではありませんでした。なぜなら、ビルドの大部分を占めるWebKitが依然としてFull LTOを使用していたからです。
• これを実行した後、Zigビルドは24分から15分に短縮されました。
• これを行った後でも、リンクには7分、ビルド全体には15分かかりました。
• 残った圧倒的な違いは構造的なものでした。Rustはコンパイルを90以上のクレートに分散させていますが、Zigビルドはすべてを単一のモジュールに集約していました。

ちなみに、トレースからは、私が無視できなかったいくつかのものも見つかりました。

ビルドに隠れていたその他のもの#

ビルドにはほぼ何でも含まれる#

BunのCIビルドの途中で、パブリックインターネットにマシンIPアドレスを問い合わせたり、実行中のDockerコンテナを検査したり、最新のGitコミットメッセージを読み取ったりするコマンドが見つかりました。

［画像: プロセスツリーに見える小さなCIセットアップコマンド］

これらはすべて合わせて1秒未満で完了します。最適化するほどのものではありませんが、ビルドトレースで見つけるとは予想していませんでした。

コールドな依存関係フェッチ#

上記のビルドはダウンロード済みの依存関係を再利用していたため、新しいWebKitフェッチも記録しました。アーカイブのダウンロードと展開には約20秒かかりました。最初の12秒間は、Nodeが実行されているだけです。その後 tar と gzip が起動され、展開が別々に確認できます。

［画像: コールドなWebKitのダウンロードと展開］

C++コンパイルの内部を見る#

以前、リンカの入力をBunのC++コンパイルまで遡って追跡しました。これらのコンパイラ呼び出しの内部も調べることができます。最後に完了したファイルの一つ、ZigGeneratedClasses.cpp を選び、そのNinjaコマンドを再実行しました（--compiler-traces 付き）。Clangの場合、buildprofは-ftime-traceを有効にし、その内部タイミングをプロセスタイムラインに追加します。[7]

［画像: ZigGeneratedClasses.cppをコンパイル中のClangのフロントエンドとバックエンドフェーズ］

再実行は約12秒かかり、Clangのフロントエンドとバックエンドでほぼ均等に分割されました。さらにズームインすると、Clangのフェーズの一つであるModuleInlinerWrapperPassが、バックエンド作業の4秒以上を占めていることがわかります。

buildprofの内部動作#

buildprofの記録側は、デバッガが使用するのと同じLinuxインターフェースであるptraceを使用しています。eBPFとftraceの両方を検討しましたが、ptraceはこの種の問題にまさに最適です。eBPFトレーシングはCAP_BPFとCAP_PERFMONの権限を必要とし、潜在的に不安定なトレースポイント/カーネル関数にフックします。一方、ftraceでは、他のユーザーの干渉を避けるためにトレーシングインスタンスを調整する必要があり、ビルドプロセスとそのすべてのdescendantのみを対象とするフィルターを完璧に設定するのは煩雑です。[8]

ptraceを使用すると、ビルドを起動し、その子プロセスを直接追跡できます。組み込みのイベントは、プロセスがフォークしたとき、新しいプログラムを実行したとき、または終了したときにbuildprofに通知します。ファイルシステムアクティビティについては、buildprofは必要な呼び出しのみをインターセプトするためにseccompフィルターを使用します。

buildprofのコストは、ビルドが開くファイルの数にほぼ完全に依存します。ripgrepの場合、記録はビルド時間にほとんど影響しませんでした。Redisはファイルを開く頻度が高く、記録によって約5秒追加されました。[9]

このオーバーヘッドが問題になる場合は、--no-file-eventsでファイルシステムトレーシングをオフにし、プロセスタイムラインを維持できます。

私はPerfettoで作業しているため、UIの自然な出発点となりました。buildprofのUIはPerfetto UIのソフトフォークです。ui.perfetto.devで録音を開くこともできましたが、プロセスツリーのレイアウト方法、コマンドをクリックしたときに表示される詳細、オンデマンドのプロデューサーとコンシューマー間の矢印のようなものについて制御したかったのです。

幸いなことに、私たちは過去数年間、プラグインを通じてPerfetto UIを拡張可能にする作業を行ってきました。buildprofのUIのほとんどは、このインフラストラクチャを再利用しています。Perfettoは難しい部分（トレースの解析、イベントのクエリ、タイムラインのレンダリング、ワークスペースの管理）を処理し、私はそれらをビルドに役立つものにする作業に集中できます。

レコーダーとUIの詳細については、別の技術記事で詳しく説明する予定です。購読して通知を受け取ってください！:)

新しいツールを構築する必要がありましたか？#

最近は、できるからという理由だけでツールを作成するのは非常に簡単です。しかし、今回はそうではありませんでした。buildprofを構築する前に、このビューを提供できる既存のツールを長時間探し回りました。

私は何度も使用したことのあるninjatracingから始めました。これはNinjaのビルドログを、何が実行され、どれだけ並列実行されたかを示すタイムラインに変換します。

Zig時代のビルドのNinjaログはこちらです。

しかし、NinjaはBunのビルドの一部しか認識しません。それを呼び出すスクリプトはログから欠落しており、実行されるコマンドは、サブプロセスのツリー全体を起動する場合でも単一のブロックとして表示されます。

問題の異なる部分をカバーする、いくつかの他のツールがありました。

• CargoのタイミングはCargo管理のビルドにはうまく機能しますが、build.rs内の任意の作業を分解したり、Cargoの上位のラッパースクリプトを見たりすることはできません。Bunでは、Cargoはビルドの一部にすぎません。キャプチャしたレポートは、5分40秒のCIビルドのうち1分51秒をカバーしていました。
• Clangの-ftime-traceはコンパイラ呼び出し内の詳細を提供しますが、コンパイラが実行されている間にビルドの残りが何をしているかを示すことはできません。ZigのTracy統合はさらに深く掘り下げられ、コンパイラ自体を理解することを目的としています。
• straceとtracexecは、forkとexecを通じて任意のプロセスを追跡できますが、ビルド指向のタイムラインではなく、一般的なプロセスイベントを表示します。

What the Fork（via）が最も近いものでした。ビルドシステムを横断してプロセスを追跡し、ビルド固有のビューを提供します。しかし、私の知る限り、それはまだプライベートベータ版であり、オープンソース化の計画はないようです。

buildprofの今後#

buildprofはすでに私が望んでいたことを実行しており、自分のビルドで使用しながら改善を続ける予定です。しかし、改善したい点がいくつかあります。

記録オーバーヘッドがその一つです。Redisの測定値は、特に多くのファイルを開くビルドにおいて、ファイルシステムトレーシングを改善する余地があることを示しました。また、作業の一部を行っているmacOSや、関心があればWindowsのサポートも追加したいです。

テストしたいビルドシステムやツールチェーン（npm、Gradle、Bazelなど）もさらにあります。クリティカルパスの計算も大きな改善になるでしょう。この投稿では依存関係を手動で追跡しましたが、buildprofはビルドを遅延させている作業チェーンを特定し、自動的に注釈を付けるのに役立つ可能性があります。

これらは必要に応じて、必要になったときに取り組むことになるでしょう。しかし、buildprofを試してみて、何か「こうだったらいいのに」と思うことがあれば、ぜひ教えてください。人々が何を見つけるかが、私がどこに時間を費やすかを決定するのに役立ちます。

結論#

好奇心は満たされましたが、予想よりも多くの時間を費やすことになりました。その過程で、ビルドが遅すぎる場合に常に手元に置いておきたいツールを構築しました。

次に遅いビルドに悩まされたとき、buildprofに戻ることはわかっています。あなたもそのようなビルドを持っているなら、ぜひ試してみてください。何を見つけるか聞くのが楽しみです！