Go ブログ
より強力な Go 実行トレース
runtime/trace パッケージには、Go プログラムを理解してトラブルシューティングするための強力なツールが含まれています。この機能により、一定期間内の各ゴルーチンの実行を追跡できます。また、go tool trace コマンド（または、優れたオープンソースのgotraceui ツール）を使用すると、これらのトレース内のデータを視覚化して探索できます。
トレースの利点は、他の方法では把握しにくいプログラムに関する情報を簡単に明らかにできることです。たとえば、多数のゴルーチンが同じチャネルでブロックされるコンカレンシーのボトルネックは、サンプルを実行できる実行がなかったため、CPU プロファイルではなかなか検出できない場合があります。しかし、実行トレースでは、実行の欠如が驚異的な明瞭さで表示され、ブロックされたゴルーチンのスタックトレースはすぐに犯人を指し示します。
Go 開発者は自分たちのプログラムをタスク、領域、ログでインストルメントでき、それらを使用して下位レベルの実行の詳細とより高レベルの懸念事項との関連付けが可能です。
問題
残念ながら、実行トレースの情報量は多く、アクセスできることが少ない場合がよくあります。トレースには、歴史的に、4 つの大きな問題がありました。
- トレースにはオーバーヘッドが高かった。
- トレースはうまくスケーリングせず、大きすぎて分析できない可能性がありました。
- 特定の不適切な動作をキャプチャするためにトレースを開始するタイミングが明確でないことがよくありました。
- 実行トレースを解析および解釈するための公開パッケージがなく、最も冒険的な Go プログラマーのみがプログラムでトレースを分析できました。
過去数年間でトレースを使用している場合、これらの問題の 1 つ以上に悩まされている可能性があります。しかし、この最新の 2 つの Go リリースでは、これら 4 つの領域のすべてにおいて大きな進歩を遂げたことをお知らせできることを嬉しく思います。
低オーバーヘッドのトレース
Go 1.21 より前は、トレースを実行するランタイムのオーバーヘッドは多くのアプリケーションで 10～20% の CPU を占めていました。そのため、トレースは状況に応じた用途に限定され、CPU プロファイリングなどの継続的な用途には適していませんでした。トレースのコストの多くがトレースバックによるものであることが明らかになりました。ランタイムによって生成されるイベントの多くには、実行中のキーとなる瞬間ごとに、goroutine が何を実行していたかを実際に特定するために不可欠なスタックトレースが添付されています。
Felix Geisendörfer と Nick Ripley によるトレースバックの効率化の成果により、実行トレースにおけるランタイム CPU のオーバーヘッドは劇的に削減され、多くのアプリケーションで 1～2% にまで低減されました。この件についての Felix のすばらしいブログ記事 で、この成果の詳細を読むことができます。
スケーラブルなトレース
トレース形式とそのイベントは比較的効率的なエミッションを中心に設計されましたが、トレース全体の状態を解析して保持するためのツールが必要でした。数百 MiB のトレースには、解析に数 GiB の RAM が必要になる可能性があります。
残念ながら、この問題はトレースの生成方法に根本的に起因します。ランタイムのオーバーヘッドを低く抑えるために、すべてのイベントはスレッドローカルバッファの同等物に書き込まれます。しかし、これによりイベントは本来の順序ではなくなり、何が実際に起こったかを把握する負担がトレースツールに課されます。
オーバーヘッドを低く抑えながらトレースをスケーラブルにするための重要なヒントは、生成されるトレースを適宜分割することでした。各分割ポイントは、トレースを同時に無効にして再有効にするような動作を行います。これまでのすべてのトレースデータは完全で自己完結型のトレースを表し、新しいトレースデータは中断したところからシームレスに再開します。
想像できるかもしれませんが、これを修正するには ランタイムでのトレース実装の基盤の多くを再考して書き直す 必要がありました。この成果は Go 1.22 に搭載され、現在は一般公開されています。 書き換えには多くの優れた改善 が含まれ、go tool trace コマンド の改善も含まれます。気になる場合は、すべての詳細が 設計ドキュメント に記載されています。
（注: go tool trace はトレース全体をメモリに読み込みますが、Go 1.22 以降のプログラムで生成されたトレースについては、この制限を解除 することが可能になりました。）
フライトレコーディング
Web サービスに取り組んでいて、RPC に非常に長い時間がかかったとします。RPC がすでに時間がかかっていることがわかった時点でトレースを開始することはできません。その遅延要求の根本原因はすでに発生していて記録されていないからです。
これを解決できるフライトレコーディングと呼ばれる技術があります。これは他のプログラミング環境ですでに知っている可能性があります。フライトレコーディングの洞察は、トレースを継続的にオンにし、万が一の場合に最新のトレースデータを常に保持することです。その後、興味深いことが起こったら、プログラムはその時点で保持しているものを書き出すだけです。
トレースを分割できる前は、これはほとんど不可能でした。しかし、オーバーヘッドが低いため、継続的なトレースが実行可能になり、ランタイムがいつでもトレースを分割できるようになったため、フライトレコーディングの実装は容易になりました。
そこで、golang.org/x/exp/trace package で利用可能なフライトレコーダー実験を発表できることを嬉しく思います。
ぜひお試しください。次に示す例ではフライトレコーディングを設定して開始時に長い 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))
ポジティブでもネガティブでも、ご意見がございましたら 提案に関する issue で共有してください。
トレースリーダー 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)
フライトレコーダーと同様、フィードバックを残すのに最適な 提案に関する issue があります。
早期に試して、優れたフィードバックを提供し、古いバージョンのトレースに対するサポートを API に提供してくれた Dominik Honnef をすばやく指摘したいと思います。
ありがとうございます。
この作業は、1 年以上にわたって Go コミュニティ全体の関係者間のコラボレーションとして開始され、一般公開されているDiagnostics ワーキンググループのメンバーの支援により、かなりの部分が完了しました。
この 1 年間、診断会議に定期的に出席してくれた Felix Geisendörfer、Nick Ripley、Rhys Hiltner、Dominik Honnef、Bryan Boreham、thepudds といったコミュニティメンバーに感謝したいと思います。
みなさんが参加した議論、フィードバック、作業が、私たちを今日の状態に導く上で不可欠でした。ありがとうございました。