Go 1.25のフライトレコーダー

Flight Recorder in Go 1.25 by Carlos Amedee and Michael Knyszek

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

実行トレース

まず、Goの実行トレースについて簡単におさらいしておきましょう。

Goランタイムは、Goアプリケーションの実行中に発生する多くのイベントを記録したログを書き出せます。 このログはランタイム実行トレースと呼ばれます。Goの実行トレースには、ゴルーチン同士やその下にあるシステムとの 相互作用について、膨大な情報が含まれています。これによって、ゴルーチンが実行されているタイミングだけでなく、 決定的に重要な「実行されていない」タイミングまでわかるため、レイテンシの問題のデバッグに役立ちます。

runtime/traceパッケージは、runtime/trace.Startとruntime/trace.Stopを 呼び出すことで、指定した時間帯にわたる実行トレースを収集するAPIを提供しています。トレース対象のコードが 単なるテストやマイクロベンチマーク、コマンドラインツールであれば、この方法でうまくいきます。実行全体を 最初から最後までトレースすることも、関心のある部分だけをトレースすることもできます。

しかし、Goが得意とするような長時間稼働するWebサービスでは、この方法では不十分です。Webサーバは数日、 あるいは数週間にわたって稼働し続けることがあり、実行全体のトレースを収集すると、ふるいにかけるにはあまりに 大量のデータが生成されてしまいます。多くの場合、問題が起きるのはプログラムの実行のうちのほんの一部、 たとえばリクエストのタイムアウトやヘルスチェックの失敗といった箇所だけです。しかし、それが起きた時点では すでにStartを呼び出すには手遅れなのです！

この問題への対処法の一つは、稼働中の全マシンから実行トレースをランダムにサンプリングすることです。 このアプローチは強力で、障害になる前に問題を発見する助けにもなりますが、実現には多くのインフラが必要です。 大量の実行トレースデータを保存し、選別し、処理しなければならず、その大半にはまったく興味深い情報が 含まれていません。そして、ある特定の問題の原因を突き止めようとしている場合には、このアプローチはそもそも 使い物になりません。

フライトレコーディング

そこで登場するのがフライトレコーダーです。

プログラムは何か問題が起きたことにはたいてい気づけますが、その根本原因はずっと以前に発生していることが あります。フライトレコーダーを使うと、プログラムが問題を検知した瞬間までの、直近数秒間の実行トレースを 収集できます。

フライトレコーダーは通常どおり実行トレースを収集しますが、それをソケットやファイルに書き出す代わりに、 直近数秒間分のトレースをメモリ上にバッファします。プログラムはいつでもそのバッファの内容を要求し、 問題が起きたまさにその時間帯だけをスナップショットとして取り出せます。フライトレコーダーは、 問題の箇所を直接切り出すメスのようなものです。

例

例を使ってフライトレコーダーの使い方を学びましょう。具体的には、「数当てゲーム」を実装したHTTPサーバの パフォーマンス問題を診断するために使ってみます。このサーバは/guess-numberエンドポイントを公開しており、 整数を受け取って、呼び出し元にその数が正解だったかどうかを応答します。また、1分に1回、それまでに 推測された数字すべてのレポートを別のサービスへHTTPリクエストで送信するゴルーチンもあります。

// bucketはミューテックスで保護された単純なカウンターです。
type bucket struct {
    mu      sync.Mutex
    guesses int
}

func main() {
    // クライアントが推測しうる有効な数字それぞれに対して1つのbucketを用意します。
    // HTTPハンドラは、その数字をbucketsへのインデックスとして使うことで、
    // 推測された数字を検索します。
    buckets := make([]bucket, 100)

    // 1分ごとに、各数字が何回推測されたかのレポートを送信します。
    go func() {
        for range time.Tick(1 * time.Minute) {
            sendReport(buckets)
        }
    }()

    // 推測される正解の数字を選びます。
    answer := rand.Intn(len(buckets))

    http.HandleFunc("/guess-number", func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()

        // URLのクエリ変数"guess"から数字を取得して整数に変換します。
        // そのうえで、その値を検証します。
        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
        }

        // 該当するbucketを選び、その値を安全にインクリメントします。
        b := &buckets[guess]
        b.mu.Lock()
        b.guesses++
        b.mu.Unlock()

        // クライアントに対して、推測された数字と正解かどうかを応答します。
        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はbucketsの現在の状態をリモートサービスへPOSTします。
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
    }

    // レポートデータをJSONペイロードにマーシャリングします。
    b, err := json.Marshal(counts)
    if err != nil {
        log.Printf("failed to marshal report data: 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)
    }
}

サーバの完全なコードはこちら、単純なクライアントのコードは こちらです。3つ目のプロセスを増やさないために、この「クライアント」は レポートサーバも兼ねていますが、実システムではこれらは分離されているべきでしょう。

このアプリケーションを本番環境にデプロイした後、一部の/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

先に進む前に、少し時間を取って、何がおかしいのか見つけられるか考えてみてください！

問題を見つけられたかどうかにかかわらず、さらに深く掘り下げて、原理原則から問題を見つける方法を 見ていきましょう。特に、遅い応答が起きるまでの間にアプリケーションが何をしていたかを見られれば理想的です。 これはまさにフライトレコーダーが作られた目的そのものです！ 100ミリ秒を超える最初の応答を検知した時点で、 フライトレコーダーを使って実行トレースをキャプチャすることにします。

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

// フライトレコーダーをセットアップします
fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{
    MinAge:   200 * time.Millisecond,
    MaxBytes: 1 << 20, // 1 MiB
})
fr.Start()

MinAgeは、トレースデータが確実に保持される期間を設定するもので、対象となるイベントの時間幅の およそ2倍程度に設定することをお勧めします。たとえば5秒のタイムアウトをデバッグしているのであれば、 10秒に設定します。MaxBytesは、メモリ使用量が膨れ上がらないように、バッファされるトレースのサイズを 設定します。実行1秒あたり数MB、負荷の高いサービスであれば10MB/s程度のトレースデータが生成されると 見込んでおくとよいでしょう。

次に、スナップショットをキャプチャしてファイルに書き出すためのヘルパー関数を追加します。

var once sync.Once

// captureSnapshotはフライトレコーダーのスナップショットをキャプチャします。
func captureSnapshot(fr *trace.FlightRecorder) {
    // once.Doは、渡された関数が一度だけ実行されることを保証します。
    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() // エラーは無視します

        // WriteToはフライトレコーダーのデータを渡されたio.Writerに書き込みます。
        _, err = fr.WriteTo(f)
        if err != nil {
            log.Printf("writing snapshot to file %s failed: %s", f.Name(), err)
            return
        }

        // スナップショットの取得後にフライトレコーダーを停止します。
        fr.Stop()
        log.Printf("captured a flight recorder snapshot to %s", f.Name())
    })
}

そして最後に、完了したリクエストをログ出力する直前で、そのリクエストが100ミリ秒より長くかかっていた場合に スナップショットをトリガーします。

// 応答に100ms以上かかった場合にスナップショットをキャプチャします。
// 最初の呼び出しだけが効果を持ちます。
if fr.Enabled() && time.Since(start) > 100*time.Millisecond {
    go captureSnapshot(fr)
}

フライトレコーダーを組み込んだサーバの完全なコードはこちらです。

それでは、サーバを再度実行し、スナップショットをトリガーする遅いリクエストが発生するまでリクエストを 送信してみましょう。

トレースを取得できたら、それを調べるためのツールが必要です。Goツールチェインには、 go tool traceコマンドを通じて組み込みの実行トレース解析ツールが 用意されています。go tool trace snapshot.traceを実行するとこのツールが起動し、ローカルのWebサーバが 立ち上がるので、（ツールが自動でブラウザを開かない場合は）表示されたURLをブラウザで開いてください。

このツールにはトレースを見るためのいくつかの方法がありますが、ここでは何が起きているかを把握するために トレースを可視化する方法に絞ります。そのためには「View trace by proc」をクリックします。

このビューでは、トレースはイベントのタイムラインとして表示されます。ページ上部の「STATS」セクションには、 スレッド数、ヒープサイズ、ゴルーチン数といった、アプリケーションの状態のサマリーが表示されます。

その下の「PROCS」セクションでは、ゴルーチンの実行がGOMAXPROCS（Goアプリケーションが作成するOSスレッドの数） にどのようにマッピングされているかを確認できます。それぞれのゴルーチンがいつ、どのように開始し、 実行され、最終的に停止するのかがわかります。

ここでは、ビューアの右側にある実行の大きなギャップに注目してみましょう。およそ100ミリ秒の間、 何も起きていません！

ズームツールを選択する（あるいは3キーを押す）ことで、そのギャップの直後の部分をより詳しく調べることが できます。

個々のゴルーチンの動きに加えて、「フローイベント」を通じてゴルーチン同士がどのように相互作用しているかも 見られます。入ってくるフローイベントは、あるゴルーチンが実行を開始するきっかけとなった出来事を 示します。出ていくフローエッジは、あるゴルーチンが別のゴルーチンに与えた影響を示します。すべてのフロー イベントの可視化を有効にすると、問題の原因を示す手がかりが得られることがよくあります。

今回の場合、活動が止まった直後、多くのゴルーチンが1つのゴルーチンと直接つながっていることがわかります。

そのゴルーチンをクリックすると、出ていくフローイベントで埋め尽くされたイベントテーブルが表示され、 これはフロービューを有効にしたときに見たものと一致します。

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

このゴルーチンが実行を開始してから終了するまでの間に、他のゴルーチンと相互作用する大量の「出ていくフロー」が 見られます。Outgoing flowのエントリのいずれかをクリックすると、その相互作用のビューに移動します。

このフローはsendReport内のUnlockが原因であることを示しています。

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

    counts[index] = b.guesses
}

sendReportでは、各bucketのロックを取得し、値をコピーした後にロックを解放するつもりでした。

しかし、ここに問題があります。実際には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）です。

皆さんが重ねてきた議論、フィードバック、そして取り組みは、より良い診断機能の未来へ私たちを前進させる 大きな力になりました。ありがとうございます！

By Carlos Amedee and Michael Knyszek