Yoshi Yamaguchi

より強力になったGoの実行トレース

More powerful Go execution traces by Michael Knyszek

runtime/traceパッケージには、Goプログラムを理解し、 トラブルシューティングするための強力なツールが含まれています。この機能を使うと、 ある期間における各ゴルーチンの実行内容のトレースを生成できます。 go tool traceコマンド（あるいは優れたオープンソースツールである gotraceui）を使えば、これらのトレースに含まれるデータを可視化し、 探索できます。

トレースの真骨頂は、他の方法では見えにくいプログラムの実態を簡単に明らかにできることです。 例えば、多数のゴルーチンが同じチャネルでブロックしているような並行性のボトルネックは、 サンプリングすべき実行そのものが存在しないため、CPUプロファイルでは見つけるのが非常に 難しいことがあります。しかし実行トレースでは、実行の 不在 こそが驚くほど明瞭に浮かび上がり、 ブロックしているゴルーチンのスタックトレースがすぐさま原因を指し示してくれます。

gotooltrace

Goの開発者は、task、 region、 logを使って自分のプログラムに計装を施し、 アプリケーションレベルの関心事とより低レベルな実行の詳細を関連付けることさえできます。

課題

残念ながら、実行トレースに含まれる豊富な情報は、しばしば手の届かないところにありました。 歴史的に、トレースには4つの大きな問題が立ちはだかってきました。

  • トレースのオーバーヘッドが高かった。
  • トレースはスケールせず、大きくなりすぎて解析できなくなることがあった。
  • 特定の不具合を捉えるためにいつトレースを開始すればよいのかがしばしば不明瞭だった。
  • 実行トレースを解析し解釈するための公開パッケージが存在しなかったため、トレースをプログラムから 解析できるのは一部の物好きなgopherに限られていた。

過去数年でトレースを使ったことがあるなら、これらの問題のうち一つ以上に不満を抱いたことがあるでしょう。 しかし、直近のGoの2つのリリースにわたって、これら4つの領域すべてで大きく前進したことを 喜んでお伝えします。

低オーバーヘッドなトレーシング

Go 1.21より前は、多くのアプリケーションにおいてトレーシングの実行時オーバーヘッドはCPUの 10〜20%程度もあり、それによってトレーシングはCPUプロファイリングのような継続的な利用ではなく、 状況に応じた限定的な利用に限られていました。トレーシングのコストの大半は、実はトレースバック （traceback）に起因することがわかりました。ランタイムが生成する多くのイベントにはスタック トレースが付随しており、これはゴルーチンが実行中の重要な瞬間に何をしていたかを実際に特定する上で 非常に貴重な情報です。

Felix GeisendörferとNick Ripleyによるトレースバックの効率化に関する取り組みのおかげで、 実行トレースの実行時CPUオーバーヘッドは劇的に削減され、多くのアプリケーションで1〜2%程度にまで 下がりました。このテーマについて行われた作業の詳細は、 Felixによる素晴らしいブログ記事 で読めます。

スケーラブルなトレース

トレースのフォーマットとそのイベントは、比較的効率的な出力を前提として設計されていましたが、 トレース全体の状態を解析し保持するためのツール側の対応が必要でした。数百MiBのトレースを解析する だけで、数GiBのRAMが必要になることさえありました。

この問題は、残念ながらトレースが生成される仕組みそのものに起因しています。実行時オーバーヘッドを 低く抑えるため、すべてのイベントはスレッドローカルなバッファに相当する場所に書き込まれます。 しかし、これはイベントが本来の順序とは異なる順序で現れることを意味しており、実際に何が起きたのかを 突き止める負担はトレースツール側にのしかかっていました。

トレースをオーバーヘッドを低く保ったままスケールさせるための着眼点は、生成中のトレースを 時々分割することでした。分割される各時点は、トレーシングを一旦無効化してから即座に再度有効化する のとほぼ同じように振る舞います。それまでのすべてのトレースデータは、それだけで完結した一つの トレースとなり、一方で新しいトレースデータはそこで終わった地点から途切れることなく続いていきます。

想像がつくと思いますが、これを実現するには ランタイム内のトレース実装の基盤の多くを見直し、書き直す 必要がありました。この作業がGo 1.22に取り込まれ、現在一般に利用可能になったことをお知らせできて 嬉しく思います。この書き直しに伴って 数多くの素晴らしい改善がもたらされ、 その中にはgo tool traceコマンドへの改善も含まれています。 興味があれば、設計ドキュメント に細かい内容がすべて書かれています。

（注: go tool traceは依然としてトレース全体をメモリに読み込みますが、Go 1.22以降のプログラムが 生成するトレースについては、この制限を取り除くことが今や現実的に 可能になっています。）

フライトレコーディング

ウェブサービスの開発に携わっていて、あるRPCの処理に非常に長い時間がかかったとしましょう。 そのRPCの遅さに気づいた時点でトレーシングを開始しても、もう手遅れです。遅いリクエストの 根本原因はすでに発生しており、記録されていないからです。

この問題を解決する助けになる、フライトレコーディングと呼ばれる手法があります。これは他のプログラミング 環境ですでにご存知の方もいるかもしれません。フライトレコーディングの着眼点は、トレーシングを 常時有効にしておき、念のため直近のトレースデータを保持しておくというものです。そして、何か 興味深いことが起きた時点で、プログラムはその時点で保持しているデータをそのまま書き出せばよいのです。

トレースを分割できるようになる前は、これはほぼ実現不可能な話でした。しかし、低オーバーヘッド化に よって継続的なトレーシングが現実的になり、さらにランタイムが必要な時にいつでもトレースを分割 できるようになったことで、フライトレコーディングの実装は簡単だとわかりました。

その成果として、golang.org/x/exp/traceパッケージ でフライトレコーダーの実験的機能を公開できることを嬉しく思います。

ぜひ試してみてください。以下に、長時間かかったHTTPリクエストを捕捉するためのフライトレコーディングを セットアップする例を示します。

// フライトレコーダーをセットアップします。
fr := trace.NewFlightRecorder()
fr.Start()

// HTTPサーバをセットアップして実行します。
var once sync.Once
http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
    start := time.Now()

    // 処理を実行します。
    doWork(w, r)

    // 長いリクエストを検出したので、スナップショットを取得します。
    if time.Since(start) > 300*time.Millisecond {
        // 単純化のため一度だけ実行しますが、複数回取得しても構いません。
        once.Do(func() {
            // スナップショットを取得します。
            var b bytes.Buffer
            _, err = fr.WriteTo(&b)
            if err != nil {
                log.Print(err)
                return
            }
            // ファイルに書き出します。
            if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
                log.Print(err)
                return
            }
        })
    }
})
log.Fatal(http.ListenAndServe(":8080", nil))

ポジティブなものでもネガティブなものでも、何かフィードバックがあれば、ぜひ プロポーザルのissueで共有してください。

トレースリーダーAPI

トレース実装の書き直しと並行して、go tool traceのような他のトレース内部実装を整理する取り組みも 行われました。これがきっかけとなり、公開して差し支えないほど十分に良く、トレースをより扱いやすくする トレースリーダーAPIを作る試みが始まりました。

フライトレコーダーと同様に、私たちが共有したい実験的なトレースリーダーAPIも用意できたことを 嬉しく思います。これはフライトレコーダーと同じパッケージ、golang.org/x/exp/trace で利用できます。

このAPIはその上に何かを構築し始めるのに十分な出来だと考えているので、ぜひ試してみてください。 以下に、ゴルーチンのブロックイベントのうちネットワークの待機によるものの割合を計測する例を示します。

// 標準入力からの読み込みを開始します。
r, err := trace.NewReader(os.Stdin)
if err != nil {
    log.Fatal(err)
}

var blocked int
var blockedOnNetwork int
for {
    // イベントを読み込みます。
    ev, err := r.ReadEvent()
    if err == io.EOF {
        break
    } else if err != nil {
        log.Fatal(err)
    }

    // イベントを処理します。
    if ev.Kind() == trace.EventStateTransition {
        st := ev.StateTransition()
        if st.Resource.Kind == trace.ResourceGoroutine {
            from, to := st.Goroutine()

            // ゴルーチンがブロックした場合を探し、カウントします。
            if from.Executing() && to == trace.GoWaiting {
                blocked++
                if strings.Contains(st.Reason, "network") {
                    blockedOnNetwork++
                }
            }
        }
    }
}
// 結果を表示します。
p := 100 * float64(blockedOnNetwork) / float64(blocked)
fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)

フライトレコーダーと同様に、フィードバックを残すのにうってつけの場所として プロポーザルのissueを用意しています。

このAPIを早くから試し、素晴らしいフィードバックを寄せてくれた上、古いバージョンのトレースへの 対応をこのAPIに貢献してくれたDominik Honnef氏にも、この場を借りて感謝を伝えたいと思います。

謝辞

この成果は、1年以上前に発足し、Goコミュニティ全体のステークホルダーによる、そして一般に開かれた 協力の場である診断ワーキンググループに集まった皆さんの助けが あったからこそ実現できたものです。

この1年、診断ミーティングに定期的に参加してくださったコミュニティメンバーの皆さん、Felix Geisendörfer氏、Nick Ripley氏、Rhys Hiltner氏、Dominik Honnef氏、Bryan Boreham氏、thepudds氏に、 この場を借りて感謝を伝えたいと思います。

皆さんが重ねてきた議論、フィードバック、そして取り組みは、私たちを今日この場所まで導いてくれる 上で欠かせないものでした。ありがとうございます！

By Michael Knyszek