これはなに?
Go 1.19のRelease Notesを眺めていたら、runtime/pprof でgoroutine profileを取得する際のSTW(Stop-the-world)の一時停止時間が大幅に短縮され、アプリケーションに対する全体的なレイテンシーの影響が軽減されたという記述を見つけました
runtime/pprof
Stop-the-world pause times have been significantly reduced when collecting goroutine profiles, reducing the overall latency impact to the application.
個人的にどのような変更でSTWの時間が軽減されたのか気になったので追ってみました
変更を探す
1.19に入ったどの修正が対象なのかを探すために、Githubから runtime/pprof 配下の変更履歴を見てみたけど、対象っぽいものを見つけられませんでした
しかし、Release Notesに significantly reduced って記載するくらいなので、絶対に速度検証もしてるはずで、別の場所の変更で大幅に改善したのかと思い、 runtime 側を探してたらそれっぽいcommitを見つけられました
commitはこちら
Gerrit上だとこちら
https://go-review.googlesource.com/c/go/+/387415
関係するProposal
そもそものissueはこちら
大量のgoroutineを扱うアプリケーションだとgoroutine profileのレイテンシーが厳しいよって感じです
goroutineの量に比例してgoroutine profileの時間が伸びてるよって話
関係するProposalはこちら
内容としては SetMaxDumpGoroutine を追加して、dumpするgoroutineの数に制限をつけちゃえって感じです
PRも出されてます
でもこのProposalはdeclineされた模様
理由としては CL387415 で様子を見て、それでもだめならその時に考えよう
we should hold off on adding any new API right now, which we would be stuck with forever. って感じのようです
変更内容
そもそもgoroutine profileは、アプリ内のすべてのgoroutineの一貫したスナップショットを取得するためにSTWする必要があります
アプリ内の全ゴルーチンのスナップショットを取得する必要があり、allgs の反復中にSTWしたままにすると、アプリ内のgoroutineの数に比例して一時停止することになります
この変更ではその代わりに、STWしてる間に一定量のbookkeepingだけ行うようにしています
バリアを導入して、goroutineの実行を許可する前に、goroutineがprofileに表示されることをスケジューラーが確認し、そのスタックがSTW中とまったく同じように記録されるようにします
アプリが通常の操作を再開している間、allgs を反復処理し、その間にスケジュールされていない限り (自分自身をプロファイリングしていない限り)、それぞれをprofileに追加します
最後にもう一度STWしてバリアを取り除き、一定量のクリーンアップ作業を行います
これによる影響で、GoroutineProfile の固定オーバーヘッドとゴルーチンごとの CPU 時間コストの両方が増加してます
また、スケジューラーが他のゴルーチンを実行するために呼び出しを中断する可能性があるため、GoroutineProfile への呼び出しのwall-clock latencyも増加してます
この辺はトレードオフなので仕方ないところかなと
コードの変更点
Goroutine scheduler
コードの変更点を見ていく前にそもそもGoroutine schedulerの動きとか変数とかを把握していないと読みにくいので、最初にこの辺を読んでおくとスムーズかと思います
とりあえずこれが頭に入っていると、雰囲気は掴めるとは思います
// The main concepts are: // G - goroutine. // M - worker thread, or machine. // P - processor, a resource that is required to execute Go code. // M must have an associated P to execute Go code, however it can be // blocked or in a syscall w/o an associated P.
Design Docのリンクも置いておきます
いままで
いままではシンプルに世界を止めて、すべてのg分(allgs)を反復処理して、世界を再開させていた模様
変更点
gにstatus管理するためのフィールドが追加されました
StatusはgoroutineProfileState で(Absent,InProgress,Satisfied)があります
profileの状態管理用の変数も新たに切られていて
var goroutineProfile = struct {
sema uint32
active bool
offset atomic.Int64
records []StackRecord
labels []unsafe.Pointer
}
STWして状態を書き込むようにしてます
その後、世界を再開させてから、profileされるべきgoroutineか確認して
goroutine profileに書き込むようになってます
オーバーヘッドの原因はこの辺でチェック処理が入ったことによる影響だと思われます
最後にクリーンアップ処理をSTWして行ってます
まとめ
ちょっと気になってたので、どのようにpprofのgoroutine profileのSTWの時間を削減したのか調べてみました
簡単にまとめると
STWしてgoroutineの数だけ反復処理をしてprofileを取得していた処理を
STWしてgoroutineの数だけbookkeepingだけ行い
世界を再開してからbookkeepingされた情報を元にgoroutine profileの書き込みを行うようにした
その影響でgoroutine profileの固定オーバーヘッドとCPU時間コストが少し増えた
って感じだと思われます
goroutineの数が多いアプリケーションを作ってる人にはうれしい修正だったのではないかと思いました 今後はgoroutineの数が多いアプリケーションを作っている人も安心してprofilingができるので、ぜひとも取得することをおすすめします
逆に、あまりgoroutineの数が多くないアプリケーションの場合はオーバーヘッドが増えただけかもしれません とはいえ、問題になるようなオーバーヘッドではないと思われるのでprofileはどんどん取得して問題はないかなと思います
それではみなさん、ハッピーはProfiling Lifeを!
