フライトレコーダー：新しいGo実行トレーサー

2024年、私たちはより強力なGoの実行トレースを世界に紹介しました。そのブログ記事では、新しい実行トレーサーで解放できる新機能の一部を垣間見せました。その中にはフライトレコーディングも含まれていました。フライトレコーディングがGo 1.25で利用可能になったことをお知らせできることを嬉しく思います。これはGoの診断ツールボックスにおける強力な新しいツールです。

実行トレース

まず、Goの実行トレースについて簡単に振り返ってみましょう。

\ Goランタイムは、Goアプリケーションの実行中に発生する多くのイベントを記録するログを書き込むことができます。このログはランタイム実行トレースと呼ばれます。Go実行トレースには、ゴルーチンが互いにどのように相互作用し、基盤となるシステムとどのように相互作用するかについての豊富な情報が含まれています。これにより、ゴルーチンがいつ実行されているか、そして重要なことに、いつ実行されていないかを教えてくれるため、レイテンシの問題をデバッグするのに非常に便利です。

\ runtime/traceパッケージは、runtime/trace.Startとruntime/trace.Stopを呼び出すことで、特定の時間枠にわたる実行トレースを収集するためのAPIを提供します。これは、トレースするコードがテスト、マイクロベンチマーク、またはコマンドラインツールである場合にうまく機能します。完全なエンドツーエンドの実行のトレース、または気にかけている部分だけのトレースを収集することができます。

\ しかし、Goが得意とするアプリケーションの種類である長時間実行されるウェブサービスでは、それでは十分ではありません。ウェブサーバーは数日、あるいは数週間稼働し続けることがあり、実行全体のトレースを収集すると、膨大なデータが生成され、それを調べるのは大変です。多くの場合、プログラムの実行の一部だけが問題を起こします。例えば、リクエストがタイムアウトしたり、ヘルスチェックが失敗したりします。それが発生した時点では、すでにStartを呼び出すには遅すぎるのです！

\ この問題に対するアプローチの一つは、フリート全体から実行トレースをランダムにサンプリングすることです。このアプローチは強力であり、問題が障害になる前に発見するのに役立ちますが、開始するには多くのインフラストラクチャが必要です。大量の実行トレースデータを保存し、トリアージし、処理する必要があり、その多くは全く興味深いものを含んでいないかもしれません。そして、特定の問題の根本原因を突き止めようとしている場合、これは始まりにもなりません。

フライトレコーディング

これでフライトレコーダーの出番です。

\ プログラムは何かが間違っていることを知っていることが多いですが、根本原因はずっと前に発生していたかもしれません。フライトレコーダーを使用すると、プログラムが問題を検出した瞬間までの最後の数秒間の実行トレースを収集することができます。

\ フライトレコーダーは通常通り実行トレースを収集しますが、それをソケットやファイルに書き出す代わりに、トレースの最後の数秒間をメモリにバッファリングします。任意の時点で、プログラムはバッファの内容をリクエストし、問題のある時間枠を正確にスナップショットすることができます。フライトレコーダーは、問題領域に直接切り込むメスのようなものです。

例

例を使ってフライトレコーダーの使い方を学びましょう。具体的には、「数字を当てる」ゲームを実装するHTTPサーバーのパフォーマンス問題を診断するために使用してみましょう。このサーバーは/guess-numberエンドポイントを公開しており、整数を受け取り、呼び出し元に正しい数字を当てたかどうかを知らせます。

\ また、1分に1回、すべての推測された数字のレポートを別のサービスにHTTPリクエストを介して送信するゴルーチンもあります。

// bucket is a simple mutex-protected counter. type bucket struct { mu sync.Mutex guesses int } func main() { // Make one bucket for each valid number a client could guess. // The HTTP handler will look up the guessed number in buckets by // using the number as an index into the slice. buckets := make([]bucket, 100) // Every minute, we send a report of how many times each number was guessed. go func() { for range time.Tick(1 * time.Minute) { sendReport(buckets) } }() // Choose the number to be guessed. answer := rand.Intn(len(buckets)) http.HandleFunc("/guess-number", func(w http.ResponseWriter, r *http.Request) { start := time.Now() // Fetch the number from the URL query variable "guess" and convert it // to an integer. Then, validate it. guess, err := strconv.Atoi(r.URL.Query().Get("guess")) if err != nil || !(0 <= guess && guess < len(buckets)) { http.Error(w, "invalid 'guess' value", http.StatusBadRequest) return } // Select the appropriate bucket and safely increment its value. b := &buckets[guess] b.mu.Lock() b.guesses++ b.mu.Unlock() // Respond to the client with the guess and whether it was correct. fmt.Fprintf(w, "guess: %d, correct: %t", guess, guess == answer) log.Printf("HTTP request: endpoint=/guess-number guess=%d duration=%s", guess, time.Since(start)) }) log.Fatal(http.ListenAndServe(":8090", nil)) } // sendReport posts the current state of buckets to a remote service. func sendReport(buckets []bucket) { counts := make([]int, len(buckets)) for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses } // Marshal the report data into a JSON payload. b, err := json.Marshal(counts) if err != nil { log.Printf("failed to marshal report error=%s", err) return } url := "http://localhost:8091/guess-number-report" if _, err := http.Post(url, "application/json", bytes.NewReader(b)); err != nil { log.Printf("failed to send report: %s", err) } }

サーバーの完全なコードはこちら：https://go.dev/play/p/rX1eyKtVglF、そして簡単なクライアントはこちら：https://go.dev/play/p/2PjQ-1ORPiw。第三のプロセスを避けるために、「クライアント」もレポートサーバーを実装していますが、実際のシステムでは別々になるでしょう。

\ アプリケーションを本番環境にデプロイした後、ユーザーから一部の/guess-number呼び出しが予想よりも時間がかかっているという苦情を受けたとします。ログを見ると、応答時間が時々100ミリ秒を超えることがありますが、ほとんどの呼び出しはマイクロ秒単位です。

2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=69 duration=625ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=62 duration=458ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=42 duration=1.417µs 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=86 duration=115.186167ms 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=0 duration=127.993375ms

続ける前に、何が問題かを見つけられるか1分間考えてみてください！

\ 問題を見つけたかどうかに関わらず、もっと深く掘り下げて、基本原則から問題を見つける方法を見てみましょう。特に、遅い応答に至るまでにアプリケーションが何をしていたのかを見ることができれば素晴らしいでしょう。これはまさにフライトレコーダーが構築された目的です！最初の応答が100ミリ秒を超えるのを見たら、実行トレースをキャプチャするために使用します。

\ まず、mainでフライトレコーダーを設定して起動します：

// Set up the flight recorder fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{ MinAge: 200 * time.Millisecond, MaxBytes: 1 << 20, // 1 MiB }) fr.Start()

MinAgeはトレースデータが確実に保持される期間を設定し、イベントの時間枠の約2倍に設定することをお勧めします。例えば、5秒のタイムアウトをデバッグしている場合は、10秒に設定します。MaxBytesはバッファされたトレースのサイズを設定し、メモリ使用量が爆発しないようにします。平均して、実行の1秒あたり数MBのトレースデータが生成されると予想でき、忙しいサービスでは10MB/秒になります。

\ 次に、スナップショットをキャプチャしてファイルに書き込むヘルパー関数を追加します：

var once sync.Once // captureSnapshot captures a flight recorder snapshot. func captureSnapshot(fr *trace.FlightRecorder) { // once.Do ensures that the provided function is executed only once. once.Do(func() { f, err := os.Create("snapshot.trace") if err != nil { log.Printf("opening snapshot file %s failed: %s", f.Name(), err) return } defer f.Close() // ignore error // WriteTo writes the flight recorder data to the provided io.Writer. _, err = fr.WriteTo(f) if err != nil { log.Printf("writing snapshot to file %s failed: %s", f.Name(), err) return } // Stop the flight recorder after the snapshot has been taken. fr.Stop() log.Printf("captured a flight recorder snapshot to %s", f.Name()) }) }

\ 最後に、完了したリクエストをログに記録する直前に、リクエストが100ミリ秒以上かかった場合にスナップショットをトリガーします：

// Capture a snapshot if the response takes more than 100ms. // Only the first call has any effect. if fr.Enabled() && time.Since(start) > 100*time.Millisecond { go captureSnapshot(fr) }

\ フライトレコーダーで計測されたサーバーの完全なコードはこちら：https://go.dev/play/p/3V33gfIpmjG

\ さて、サーバーを再度実行し、スナップショットをトリガーする遅いリクエストが得られるまでリクエストを送信します。

\ トレースを取得したら、それを調査するのに役立つツールが必要です。Goツールチェーンは、go tool traceコマンドを通じて組み込みの実行トレース分析ツールを提供しています。go tool trace snapshot.traceを実行してツールを起動すると、ローカルウェブサーバーが起動し、表示されたURLをブラウザで開きます（ツールが自動的にブラウザを開かない場合）。

\ このツールはトレースを見るためのいくつかの方法を提供しますが、何が起こっているかを理解するためにトレースを視覚化することに焦点を当てましょう。「View trace by proc」をクリックしてください。

\ このビューでは、トレースはイベントのタイムラインとして表示されます。ページの上部の「STATS」セクションでは、スレッド数、ヒープサイズ、ゴルーチン数など、アプリケーションの状態の概要を見ることができます。

\ その下の「PROCS」セクションでは、ゴルーチンの実行がGOMAXPROCS（Goアプリケーションによって作成されるオペレーティングシステムスレッドの数）にどのようにマッピングされているかを見ることができます。各ゴルーチンがいつどのように開始し、実行し、最終的に実行を停止するかを見ることができます。

\ 今のところ、ビューアーの右側にある実行の巨大なギャップに注目しましょう。約100msの間、何も起こっていません！

zoomツールを選択する（または3を押す）ことで、ギャップの直後のトレースのセクションをより詳細に調査できます。

\ 各ゴルーチンの活動に加えて、「フローイベント」を通じてゴルーチンがどのように相互作用するかを見ることができます。受信フローイベントは、ゴルーチンが実行を開始するために何が起こったかを示します。送信フローエッジは、あるゴルーチンが別のゴルーチンにどのような影響を与えたかを示します。すべてのフローイベントの視覚化を有効にすると、問題の原因を示す手がかりが得られることがよくあります。

この場合、多くのゴルーチンが活動の一時停止直後に単一のゴルーチンに直接接続していることがわかります。

\ 単一のゴルーチンをクリックすると、送信フローイベントで満たされたイベントテーブルが表示され、フロービューが有効になったときに見たものと一致します。

\ このゴルーチンが実行されたとき、何が起こったのでしょうか？トレースに保存されている情報の一部は、異なる時点でのスタックトレースのビューです。ゴルーチンを見ると、開始スタックトレースは、ゴルーチンが実行されるようにスケジュールされたときにHTTPリクエストが完了するのを待っていたことを示しています。そして、終了スタックトレースは、sendReport関数がすでに戻り、レポートを送信する次のスケジュールされた時間のためにティッカーを待っていたことを示しています。

\ このゴルーチンの実行の開始と終了の間に、他のゴルーチンと相互作用する「送信フロー」の大量の数を見ることができます。Outgoing flowエントリの1つをクリックすると、相互作用のビューが表示されます。

\ このフローはsendReportのUnlockを示しています：

for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses }

\ sendReportでは、各バケットのロックを取得し、値をコピーした後にロックを解放することを意図していました。

\ しかし、ここに問題があります：bucket.guessesに含まれる値をコピーした後、実際にはロックをすぐに解放していません。ロックを解放するためにdefer文を使用したため、その解放は関数が戻るまで行われません。ループの終わりを過ぎてだけでなく、HTTPリクエストが完了するまでロックを保持しています。これは、大規模な本番システムで追跡するのが難しい微妙なエラーです。

\ 幸いなことに、実行トレースは問題を特定するのに役立ちました。しかし、新しいフライトレコーディングモードなしで長時間実行されるサーバーで実行トレーサーを使用しようとすると、おそらく膨大な量の実行トレースデータが蓄積され、オペレーターはそれを保存し、送信し、調べる必要があるでしょう。フライトレコーダーは後知恵の力を与えてくれます。それは、すでに起こった後に何が間違っていたのかをキャプチャし、迅速に原因を特定することができます。

\ フライトレコーダーは、実行中のアプリケーションの内部動作を診断するためのGo開発者のツールボックスに最新の追加です。過去数回のリリースでトレースを着実に改善してきました。Go 1.21はトレースのランタイムオーバーヘッドを大幅に削減しました。トレース形式はGo 1.22リリースでより堅牢になり、分割可能になり、フライトレコーダーのような機能につながりました。gotraceuiのようなオープンソースツールや、プログラムで実行トレースを解析する今後の機能は、実行トレースの力を活用するさらなる方法です。診断ページには、あなたが利用できる多くの追加ツールが記載されています。Goアプリケーションを書き、改良する際にそれらを活用していただければ幸いです。

謝辞

診断会議に積極的に参加し、設計に貢献し、長年にわたってフィードバックを提供してくれたコミュニティメンバーに感謝の意を表したいと思います：Felix Geisendörfer (@felixge.de)、Nick Ripley (@nsrip-dd)、Rhys Hiltner (@rhysh)、Dominik Honnef (@dominikh)、Bryan Boreham (@bboreham)、そしてPJ Malloy (@thepudds)。

\ 皆さんの議論、フィードバック、そして取り組みは、より良い診断の未来に向けて私たちを推進する上で非常に重要でした。ありがとうございます！

Carlos Amedee and Michael Knyszek

\ この記事は The Go Blog でCC BY 4.0 DEEDライセンスの下で利用可能です。

\ 写真：Lukas Souza on Unsplash

\