The Go Blog

より強力なGo実行トレース

Michael Knyszek
2024年3月14日

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

トレースの魔法は、他の方法では見つけるのが難しいプログラムに関する事柄を簡単に明らかにできることです。たとえば、多数のゴルーチンが同じチャネルでブロックする同時実行性のボトルネックは、CPUプロファイルではサンプリングする実行がないため、見つけるのが非常に難しい場合があります。しかし、実行トレースでは、実行の「不足」が驚くほど明確に現れ、ブロックされたゴルーチンのスタックトレースがすぐに原因を特定します。

Go開発者は、タスク、リージョン、ログを使用して独自のプログラムを計測することもでき、これらを使用して高レベルの懸念と低レベルの実行詳細を関連付けることができます。

課題

残念ながら、実行トレースに存在する豊富な情報は、多くの場合、手の届かないところにありました。歴史的に、トレースには4つの大きな問題がありました。

  • トレースには高いオーバーヘッドがありました。
  • トレースはうまくスケールせず、分析するには大きくなりすぎることがありました。
  • 特定の悪しき動作を捕捉するためにいつトレースを開始すべきか、不明確なことがよくありました。
  • 実行トレースを解析および解釈するための公開パッケージがないため、プログラムでトレースを分析できるのは、最も冒険好きなゴッパーだけでした。

過去数年間でトレースを使用したことがあるなら、これらの問題の1つ以上に悩まされたことがあるでしょう。しかし、過去2回のGoリリースで、これら4つの領域すべてで大きな進歩を遂げたことをお知らせできることを嬉しく思います。

低オーバーヘッドのトレース

Go 1.21以前は、多くのアプリケーションでトレースのランタイムオーバーヘッドは10～20%のCPUでした。これにより、トレースはCPUプロファイリングのような継続的な使用ではなく、状況に応じた使用に限定されていました。トレースのコストの多くはトレースバックに起因することが判明しました。ランタイムによって生成される多くのイベントにはスタックトレースが添付されており、これは実行の重要な瞬間にゴルーチンが何をしていたかを実際に特定する上で非常に貴重です。

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リクエストをキャプチャするようにフライトレコーディングを設定する例です。

    // Set up the flight recorder.
    fr := trace.NewFlightRecorder()
    fr.Start()

    // Set up and run an HTTP server.
    var once sync.Once
    http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()

        // Do the work...
        doWork(w, r)

        // We saw a long request. Take a snapshot!
        if time.Since(start) > 300*time.Millisecond {
            // Do it only once for simplicity, but you can take more than one.
            once.Do(func() {
                // Grab the snapshot.
                var b bytes.Buffer
                _, err = fr.WriteTo(&b)
                if err != nil {
                    log.Print(err)
                    return
                }
                // Write it to a file.
                if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
                    log.Print(err)
                    return
                }
            })
        }
    })
    log.Fatal(http.ListenAndServe(":8080", nil))

肯定的なフィードバック、否定的なフィードバックを問わず、提案の課題に共有してください！

トレースリーダーAPI

トレース実装の書き換えに伴い、go tool traceのような他のトレース内部をクリーンアップする取り組みも行われました。これにより、共有するのに十分で、トレースをより利用しやすくするトレースリーダーAPIを作成する試みが生まれました。

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

これを使って何かを構築し始めるのに十分だと考えていますので、ぜひお試しください！以下は、ネットワーク待機のためにブロックされたゴルーチンブロックイベントの割合を測定する例です。

    // Start reading from STDIN.
    r, err := trace.NewReader(os.Stdin)
    if err != nil {
        log.Fatal(err)
    }

    var blocked int
    var blockedOnNetwork int
    for {
        // Read the event.
        ev, err := r.ReadEvent()
        if err == io.EOF {
            break
        } else if err != nil {
            log.Fatal(err)
        }

        // Process it.
        if ev.Kind() == trace.EventStateTransition {
            st := ev.StateTransition()
            if st.Resource.Kind == trace.ResourceGoroutine {
                from, to := st.Goroutine()

                // Look for goroutines blocking, and count them.
                if from.Executing() && to == trace.GoWaiting {
                    blocked++
                    if strings.Contains(st.Reason, "network") {
                        blockedOnNetwork++
                    }
                }
            }
        }
    }
    // Print what we found.
    p := 100 * float64(blockedOnNetwork) / float64(blocked)
    fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)

そして、フライトレコーダーと同様に、フィードバックを残すのに最適な場所となる提案の課題があります！

Dominik Honnef氏は、早期に試用し、素晴らしいフィードバックを提供し、古いトレースバージョンへのサポートをAPIに貢献してくれた方として、すぐに感謝の意を表したいと思います。

ありがとうございます！

この作業は、1年以上前にGoコミュニティ全体からのステークホルダー間の協力として開始され、一般に公開されている診断ワーキンググループの助けのおかげで、少なからず完了しました。

過去1年間、診断会議に定期的に参加してくださったコミュニティメンバーに感謝申し上げます：Felix Geisendörfer、Nick Ripley、Rhys Hiltner、Dominik Honnef、Bryan Boreham、thepudds。

皆さんが行った議論、フィードバック、そして努力は、今日の私たちの達成に不可欠でした。ありがとうございます！

次の記事：Go開発者アンケート2024年上半期の結果
前の記事：スライスに関する堅牢なジェネリック関数
ブログインデックス

go.dev は、サービスの品質を提供および向上させ、トラフィックを分析するために、Google の Cookie を使用しています。詳細はこちらをご覧ください。