pprof vs runtime/trace (FlightRecorder)

Go 1.25 リリースパーティ & GopherCon 2025 報告会での発表資料です。
ref: https://gocon.connpass.com/event/366062/

GopherCon2025で発表されたGo 1.25 リリースパーティ & GopherCon 2025 報告会に沿って、次のトピックをシェアしました:
・pprof / runtime/trace の目的と特性に関する理解
・FlightRecorder について

デモをご覧になりたい方はYouTubeのアーカイブを参照してください。
https://youtu.be/uY5Duj5m9ig

Transcript

1. 1 pprof vs runtime/trace (Flight Recorder) GC25 Recap: Profiling Request Latency with Critical Path Analysis Go 1.25 リリースパーティー @task4233
2. 2 所属 ・Mercariのバックエンドエンジニア ・IDPチームで認証認可基盤まわりの開発をしています 興味 ・バックエンドとWebセキュリティ 自己紹介: @task4233
3. 3 ・Recap の目的は、元の発表および関連するトピックの情報共有です 　・興味のあるワードがあれば、各自で深掘りしていただければ幸いです ・今回扱う内容は Go の標準パッケージの内容に限ります 　・Go のリリパなので、OpenTelemetry や eBPF などの話は扱いません🙏 ・元の発表に加えて、自分の解釈 /理解を含みます 　・それ違くないか？みたいなものがあれば、私の学びにもなるので 　　マサカリお待ちしてます はじめに: おことわり
4. 4 Recap対象セッションの概要 おしながき pprof の概要と特性 runtime/trace の概要と特性 Flight Recorder 02 03 04 01 まとめ 05
5. 5 Q. p99 だけ跳ねている エンドポイントがありました どう調査しますか？👀
6. 6 A. metrics/log を仕込むなど
7. 7 Q. それでも原因がわかりません どうしますか？🤔
8. 8 Profiling Request Latency with Critical Path Analysis ・現実世界のWebアプリケーションで「なぜ p99 レイテンシのリクエストが 　そこまで大きいのか」を明確にしたいというモチベーションから ・処理のクリティカルパスを明確にすることで、遅いリクエストの原因を 　特定するためのプロファイリング手法 を提案 ・pprof の特性に言及し、代わりに runtime/trace が提供する 　トレース情報を活用した話 1. Recap対象のセッション概要
9. 9 ・パフォーマンスプロファイルを収集/解析する必要がある 　・CPU使用率、メモリ使用率を主に計測可能な pprof がよく利用される 2. 遅いリクエストの原因を特定するためには？
10. 1 目的 ・CPU や メモリといったリソース消費のホットスポットを特定すること 仕組み ・Go ランタイムが一定の間隔でプログラムの実行を中断し、 　その瞬間の goroutine のコールスタックを記録する 　・CPU プロファイルなら、デフォルトで 10[ms] ごとに記録をとる 特性 ・「何がリソースを消費しているか」に答えられる 　・リソース消費に関する情報を収集しているので ・「なぜレイテンシが大きいのか」には答えられない pprof: 統計的なサンプリングに基づくプロファイル
11. 11 ・runtime/pprof 　・ビジュアライザが期待する形式でプロファイルを書き出す 　　サンプリングツール ・net/http/pprof 　・HTTPサーバを介して、ビジュアライザが期待する形式でプロファイルを 　　書き出すサンプリングツール (内部的に runtime/pprof を呼んでいる) 　・簡易的なビジュアライザも兼ねる ・cmd/pprof (go tool pprof) 　・プロファイルを解析して表示するツール Go が提供する pprof たち
12. 12 ・CPU利用率だけでは「特定のエンドポイントの p99 レイテンシが 　なぜ大きいのか」を正確に解析できない 　・スレッドが CPU を利用している状態のみしかキャプチャしないため 　・この状態を on-CPU と呼ぶ ・対する off-CPU は？ 　・I/Oバウンド(ネットワーク、ディスク)、Sleep、Channel、mutex 　　Syscall などのブロッキングなど 　・「待機していた」という情報は取得できるが、「待機理由」や「対象」 　　といった情報は取得できない😢 CPU プロファイルの限界 - on-CPU と off-CPU
13. 13 目的 ・プログラム内でのイベントを記録して、実行の全体像を俯瞰すること 仕組み ・各アクションに応じてイベントレコードを出力する 　・goroutine の生成、Channel、Sleep、Syscall のブロッキング 　　GC の開始など 特性 ・「なぜレイテンシが大きいのか」に答えられる 　・on/off-CPU問わず、詳細な時系列データが得られるので ・「何がリソースを消費しているか」には答えられない 3. runtime/trace: イベント記録に基づくプロファイル
14. 1 テキストでの解析
15. 15 UI での解析
16. 16 Request のアノテーション
17. 17 ・最も時間がかかる処理経路を特定し、全体レイテンシに寄与する要因を 　分析するための解析方法 　・プロジェクトマネジメントのクリティカルパスと同じ クリティカルパス解析
18. 1 goroutine が 1 つの場合
19. 19 子goroutine がある場合
20. 2 複数の goroutine に処理が広がる場合
21. 21 worker が存在する場合
22. 2 ・runtime/trace は長時間稼働する現実の Web サービスでは 　データが大量に残ってしまう問題がある 　・エンドポイントが「遅い」と分かるのは処理が終わってからなので ・そこで Flight Recorder 　・トレースをソケットやファイルに書き出さず、メモリにバッファリング 　　するツール 　・結果に応じてトレースを永続化するか決められる ・詳しくは数日前に公開された Go Blog を参照のこと 　・ref: https://go.dev/blog/flight-recorder 4. Go 1.25 の話: Flight Recorder
23. 2 pprof と runtime/trace にはそれぞれ特性がある ・pprof 　・何がリソースを消費しているか」に答えられる ・runtime/trace 　・「なぜレイテンシが大きいのか」に答えられる ・それぞれの特性に合わせた利用をすると良い(と思います) runtime/trace において、 Flight Recorder を用いることで 必要に応じた利用が可能 ・ブログで「APIを提供したから便利なツール作ってくれよな！」 　と書かれていたので、興味のある方は色々と作ってみると面白いかも まとめ
24. 2 ・https://go.dev/blog/flight-recorder ・https://go.dev/blog/execution-traces-2024 ・https://github.com/gophercon/talks ・https://pkg.go.dev/runtime/trace ・https://pkg.go.dev/runtime/pprof ・https://pkg.go.dev/runtime/pprof ・https://pkg.go.dev/net/http/pprof ・https://pkg.go.dev/cmd/pprof ・https://blog.felixge.de/reducing-gos-execution-tracer-overhead-with-frame-pointer-unwinding/ ・https://www.tetsuzawa.com/blog/performance-tuning 参考文献