メインコンテンツへスキップ
  1. Posts/

GC ポーズとレイテンシ:時間は実際どこに隠れているのか

·664 文字·4 分·
Go Kubernetes Containers Garbage-Collection Latency
アミット・デイブ
著者
アミット・デイブ
ソフトウェアエンジニアで、しっかりしたシステムを作るのが得意です。難しい問題をわかりやすくすることも得意です。好きなことは、分散システムクリーンアーキテクチャ、そしてオープンソースプロジェクトです。仕事以外では、山を歩くことや日本語の勉強、そしてstderrなどから学ぶことを楽しんでいます。
目次
Go in Containers - この記事は連載の一部です
パート 3: この記事

これはラップトップの上で、2 GB のゴミを処理し切った Go プログラムの、ストップ・ザ・ワールド予算の全部だ — 43 回のコレクションサイクル、ポーズは一つ残らず記録済み、runtime/metrics/sched/pauses/total/gc:seconds)から直接。

gc cycles: 43
pauses p50=0.0205ms p90=0.0205ms p99=0.0492ms max=0.0492ms

中央値で 20 マイクロ秒。ワーストケースでも 49 マイクロ秒、全実行を通してだ。これが go1.26.4 の、健全な箱の上での Go の二つのストップ・ザ・ワールドフェーズの値段で、じっくり見る価値がある — 「GC ポーズはミリ秒単位」という俗説は、50 倍もズレている。Go に有利な方向に。

同じコレクタ、同じマシン、今度は --cpus=0.5 のコンテナの中で。

GOMAXPROCS=2 NumCPU=6
gc cycles: 1088
pauses p50=0.0328ms p90=0.0492ms p99=83.9ms max=83.9ms

中央値はほとんど動いていない。テールは二千五百倍に爆発した。このトレースの中の一つの数字が悲鳴を全部あげていて、この記事は、その悲鳴がどこから来るのか、どうやって見るのか、そして実際に何が直すのかについての話だ — 全部の数字は実機の実行から。パート2と同じハーネスの流儀:go1.26.4、静的な linux/arm64 バイナリ、podman 上の alpine、cgroup v2。

ポーズの解剖、実際の名前付きで
#

Go の GC は、1 サイクルにつききっかり 2 回、世界を止める。ランタイムのドキュメントは、フェーズの名前を正確に呼んでいる — 「ストップ・ザ・ワールド(STW)の sweep termination、並行マーク&スキャン、そして STW の mark termination」。(この名前は gctrace の出力でもう一度出てくるから、ランタイムの綴りのまま覚えておくといい — 最初のポーズがライトバリアを入れて、二番目のポーズがマークを締める。)

両方のフェーズは小さく済むように設計されていて、さっきの健全な箱のヒストグラムは、その設計がちゃんと働いていることを見せている。でも STW ポーズには二つの要素がある — 仕事そのものと、その仕事をやらせてもらうためにスケジュールされるまでの待ちだ。GC ガイドのレイテンシのセクションは、GC が君のレイテンシを食う方法を五つ挙げている — 短い STW ポーズはその一つ目に過ぎなくて、健全なマシンならこの五つのどれも痛くない。

コンテナの中では、二番目の要素が無視できなくなる。CFS の quota は平均だ。--cpus=0.5 は「100ms の period につき CPU 時間 50ms」を意味する(カーネルの cgroup-v2 ドキュメントcpu.max)。予算を早めに使い切ると、カーネルは次の period まで、その cgroup 内の全スレッドを凍らせる。もしその凍結が、ランタイムがちょうど STW ウィンドウのにいる瞬間に来たら — goroutine は止まっていて、世界は停止していて、後片付けは半分終わったところ — ポーズはもう「仕事」じゃなくなる。「仕事 プラス CFS period の残り」になる。

掛け算、実録で
#

ハーネスはこうだ。ビジーループの goroutine が CPU を燃やし続け(P ひとつにつき一つ)、加えて 1 MiB/イテレーションのアロケーション churn、20 秒間、--cpus=0.5 のコンテナの中。二回の実行、変数は一つだけ。

実行 A — Go 1.25+ のデフォルト。 ランタイムは cgroup の quota を読んで(パート1の話)、自分の下限を選ぶ。

GOMAXPROCS=2 NumCPU=6
gc cycles: 1088
pauses p50=0.0328ms p90=0.0492ms p99=83.9ms max=83.9ms

実行 B — GOMAXPROCS=4 を強制、1.25 以前の世界か、パート1がカタログ化したオプトアウトのどれかをシミュレートする。

GOMAXPROCS=4 NumCPU=6
gc cycles: 552
pauses p50=0.0983ms p90=0.197ms p99=101ms max=101ms

実行 B の max を見てほしい。101 ミリ秒 — CFS period まるまる一つ分、プラス中断された仕事の分だ。 これは偶然じゃない。メカニズムがそのまま写真に写っている。プロセスは quota が尽きた瞬間、STW の真っ最中だった。だからポーズは、カーネルの凍結を丸ごと吸い込んだ。quota より上に走らせる P が一つ増えるたびに、予算は早く燃え、凍結がポーズウィンドウの中に落ちる確率も上がる。

そして、実行 A が言っていないことに注目してほしい。1.25 のデフォルトが君を救う、とは言っていない。GOMAXPROCS=2 は下限の値で、0.5 CPU の quota はその下限の食欲の四分の一しかないのに、テールはそれでも 84ms まで跳ねた。GOMAXPROCS を正しいサイズにすればウィンドウは狭くなる — でも、それを消してくれるのは余裕(ヘッドルーム)か、我慢だけだ。P50 は君の GC が健全かどうかを教えてくれる。P99 は君のカーネルについて教えてくれる。p99/p50 の比が三桁も違うなら、それは GC の問題じゃない — GC の服を着たスケジューリングの問題だ。

ポーズに隠れていない時、レイテンシはどこに隠れるのか
#

GC ガイドが挙げるレイテンシの発生源の全リスト — そしてここが、ほとんどの記事が飛ばす部分だ。STW ポーズは五つのうちの一項目でしかない。残りは — マーク中に GC が食うCPU 25%、割り当てのペースがコレクタを追い越した時にユーザーの goroutine が mark assist に徴用されること、ライトバリアのオーバーヘッド、そして個々の goroutine のルートスキャンの遅延 — これらはポーズので君のレイテンシを食う。そして CPU quota の下では、二重に食う。GC が使う CPU 秒はどれも、スロットルへ一秒近づく CPU 秒だからだ。

それがパート2の中心的トレードオフの請求書だから、はっきり払っておこう。GOMEMLIMIT の救出は 7 回のコレクションを 22 回に変えた。オーバーシュートの実行は 0.36 秒で 247 回も回収した。その追加サイクル一つひとつが、マークフェーズ中の約 25% の CPU、プラス STW ウィンドウ二回分、プラス君の一番熱いアロケータへの assist の圧力を持っている — 全部、リクエストハンドラが必要としているのと同じ quota に請求される。GC の頻度は、どこか別の場所で払うレイテンシだ。そしてコンテナの中では、「別の場所」は CFS のメーターだ。メーターがポーズの最中に尽きたら、実行 B になる。

assist にはもう一文だけ払う価値がある。五つの中で一番タチが悪いからだ。アロケーションがマークを追い越すと、ランタイムは割り当てているその goroutine 自身に、割り当て地点で GC の仕事をやらせる。君の P99 スパイクは、リクエストの goroutine がリクエストの途中で GC 税を払っている姿かもしれない — ポーズのヒストグラムには映らず、実行トレースの中の MARK ASSIST というスライスにしか見えない。

Green Tea:新しい計算式
#

パート2で予告した話だ。Go 1.26 は Green Tea をデフォルトのガベージコレクタにした(リリースノート:「実世界のプログラムで、ガベージコレクションのオーバーヘッドが 10〜40% 減ると見込んでいる」)。ビルド時に GOEXPERIMENT=nogreenteagc を付ければ、今でも旧コレクタと A/B できる — ただし 1.27 で消える予定の非常口だ。

Green Tea が輝くワークロードは、このシリーズがずっと殴ってきたのとまさに同じもの — ポインタ密度の高いヒープだ。百万個の *int64 を生かしたまま、10 回の強制サイクル、両方のコレクタ、同じ箱で。

--- go1.26.4 default (Green Tea):
mode=ptrs n=1000000  wall/cycle=1.30ms  gc-cpu/cycle=4.57ms
  pauses: count=20 max<=0.0492ms
--- GOEXPERIMENT=nogreenteagc:
mode=ptrs n=1000000  wall/cycle=4.40ms  gc-cpu/cycle=5.38ms
  pauses: count=20 max<=0.0492ms

大事な二行を読んでほしい。サイクルあたりの wall time は 4.40ms → 1.30ms、マークが 3.4 倍速くなった。Green Tea がメモリを連続したブロックでスキャンするからだ — ヒープのあちこちをポインタを一個ずつ追いかけるんじゃなくて。STW ポーズは変わらない — どちらのコレクタでも数十マイクロ秒のままだ。

それが正直な見出しだ。Green Tea はスループットの計算式を変える。ポーズの計算式は変えない。 君のポーズはもう元からマイクロ秒だった。今もそのままだ。縮むのは並行マークのフェーズ — CPU 25% のウィンドウ、assist の圧力、quota の消費だ。コンテナの中では、それはサイクルあたり CFS メーターに乗る CPU 秒が減るということで、つまりカーネルが君を何かの最中に凍らせるチャンスが減るということだ。掛け算のエンジンに入る燃料が減り、パート2の頻度税は、つまみを一つも触らずに 10〜40% 安くなる。

それでもポインタ密度が最大のレバーだ
#

同じベンチマーク、Green Tea、変数は一つ — 百万個の int64 対、百万個の *int64

mode=ints n=1000000  wall/cycle=0.10ms  gc-cpu/cycle=0.20ms
mode=ptrs n=1000000  wall/cycle=1.30ms  gc-cpu/cycle=4.57ms

同じ百万個の値で、GC の CPU が 23 倍違う。理由は、百万個の整数のスライスはポインタを一つも持たない、たった一つのオブジェクトだからだ — GC ガイドは、ポインタを含まないメモリはスキップするのが安上がりだ、とはっきり書いている — 一方、百万個のポインタは、追いかけるべきオブジェクトが百万個あるということだ。(俗説は「スキャン 1ms 対 100ms」と言うけど、この箱で測った差はサイクルあたり 0.2ms 対 4.6ms。方向は同じ教訓で、数字は正直に小さい。)君のヒープがポインタの藪 — []*Thingmap[string]*Entry、連結構造 — なら、それを平らにするほうが、どんな GOGC の値よりも効く。

アロケーション率のツールボックスの残りは、いつも通りだ。churn の激しいバッファには sync.Pool、ポインタのスライスより値のスライス、リクエストあたりの小さいオブジェクトを減らす。ゴミが減れば → サイクルが減り → カーネルが凍結を落とせる STW ウィンドウが減り → assist の圧力も減る。この鎖の矢印は、全部さっき測定済みだ。

チューニングのレバー、正直な順位付け
#

1. GC の仕事を減らす(アロケーション率、ポインタ密度)。 コストの表のどの行も一度に改善してくれる、唯一のレバーだ。さっき測った通り、GC の CPU で 23 倍。

2. ランタイムに正直な CPU 会計をさせる。 パート1の話全部に、今度はレイテンシの値札が付いた。0.5 CPU の quota に対して GOMAXPROCS=4 を強制すると、max ポーズは 84ms から 101ms に動き、しかも全パーセンタイルが上がった。オプトアウト(init コードの runtime.GOMAXPROCS(NumCPU)、ベースイメージの環境変数)を監査すること。

3. メモリと頻度を交換する — パート2の注意書き付きで。 GOGC を上げるとサイクルの頻度は下がり、サイクルが減ればスロットルに晒されるウィンドウも減る。でも GOMEMLIMIT の天井が GOGC の比例ターゲットより下にある時点で、GOGC はただのお荷物だ — パート2のメトロノーム実行(毎サイクル 388 MB で発動、GOGC の約 524 MiB の希望は無視される)が、その姿だ。天井の近くでは、天井がペーサーそのものになる。そこで GOGC を上げても、変わるのは君の自信だけだ。

4. Kubernetes のレバー、実際の部品ごとに分解する。 (a) スロットルが GC のウィンドウ中に起きているなら、quota がランタイムの食欲に対して狭すぎる — limit を上げるか、食欲を削れ(レバー1〜3)。(b) request ≈ limit配置の予測可能性を買う — request を超えるバースト容量はノードの隣人次第だから、大きな差はポーズのテールをノード依存で再現不能にする。(c)「CPU limit を完全に外して、request だけ残す」派は、固い天井をスケジューラの公平性と交換する — CFS period の凍結は本当になくなるが、代わりにうるさい隣人の影響を受けやすくなる。どれを選んでも、コンテナの cpu.statnr_throttled(または cAdvisor/Prometheus の container_cpu_cfs_throttled_seconds_total)を見張ること — これが登り続けているなら、ダッシュボードの平均 CPU が何と言おうと、君のポーズは増幅されている。

自分で測る
#

  • /sched/pauses/total/gc:secondsruntime/metrics、Go 1.22 以降。古い /gc/pauses:seconds もまだ生きているけど非推奨だ — 同じヒストグラムだと両方確認した)。p50 p99 の両方を追うこと。p50 は君の GC、p99 は君のカーネルだ。
  • GODEBUG=gctrace=1clock の列がフェーズごとの wall time を見せてくれる。フェーズの名前は、さっき出てきたのと同じだ。
  • go tool tracegoroutine ごとに見える唯一のビュー。リクエストの goroutine 上の MARK ASSIST のスライス、そしてスケジューラが何も走らせられなくなった時、STW ウィンドウが目に見えて伸びる様子。
  • コンテナの中で cat /sys/fs/cgroup/cpu.statnr_throttledthrottled_usec は、カーネル自身の自白だ。その伸びとポーズヒストグラムのスパイクを突き合わせるのが、診断そのもの。(パート4は、これを丸ごとワークフローにする。)

この記事のすべての数字を出したハーネスは、全部でだいたい 150 行 — コンテナ実行用のスピナー付き churn ループ(サイクル間隔を現実的にするための 50 MB のライブ・バラスト入り)、ポインタ / Green Tea の A/B 用の二モードスライスベンチマーク。CGO_ENABLED=0 GOOS=linux でビルドし、podman run --cpus=0.5 の下で、変数はただの -e GOMAXPROCS=... だけ。上の説明から10 分で自分で組み直せる — 大事なのは形であって、正確な数字じゃない。君の箱は違う数字を出すし、俺の箱でさえ、スロットルされたテールのバケツは実行のたびに 42ms と 101ms の間で跳ね回る(83.9ms が一番よく出る値で、マイクロ秒単位の中央値は絶対に動かない)。

意見としてのまとめ
#

  • 「ミリ秒単位のポーズ」って言うのはもうやめろ。 健全な go1.26.4 のポーズは数十マイクロ秒 — この箱で 43 サイクル通して max 49µs。ミリ秒が見えているなら、何かがそれを伸ばしている。ほとんどの場合、コレクタ自身のせいじゃない。
  • テールはカーネルだ。GC じゃない。 101ms = CFS period まるまる一つ、写真に写った証拠。GC のつまみを一個でも触る前に、P99 のポーズスパイクを cpu.statnr_throttled と突き合わせろ。
  • Green Tea はスループットの贈り物であって、レイテンシの贈り物じゃない — ポインタだらけのヒープでマークが 3.4 倍速くなる。ポーズは変わらない。quota が 10〜40% 楽になるのはありがたく受け取れ、でもヒストグラムが動くとは期待するな。
  • ポインタ密度は、君が持っている中で最大のレバーだ[]int64[]*int64 の間で GC の CPU が 23 倍、実測済み。チューニングの前に平らにしろ。
  • GOMEMLIMIT が GOGC の近くにある時、GOGC は何もしていない — パート2のメトロノームがそれを証明した。ペーサーが無視しているつまみから、レイテンシの勝利を予算に組むな。
  • GOMAXPROCS の正直さは、レイテンシの機能だ。 1.25 のデフォルトは、他に何も触らないまま、俺の最悪ポーズを 17ms 狭めてくれた — そして君の依存ツリーのどこかにあるオプトアウトが一つ、それを静かに広げ直している。

GC は言語の問題じゃない。コンテナの中では、メモリの問題ですらほとんどない。これはリソース同士のやり取りの問題だ。コレクタが CPU を使い、カーネルが CPU を計量し、君の P99 は二つの帳簿の隙間に住んでいる。もう両方の帳簿を読む道具は手に入った。次は、火事が起きた本番で、その二つを一緒に使うためのデバッグワークフローだ。


「コンテナの中の Go」シリーズの次回:コンテナ・デバッグの実践ワークフロー — pprof、ephemeral コンテナ、そして深夜 3 時に scratch イメージから信号を引っ張り出す話。


「コンテナの中の Go」シリーズ: イントロ — サイレント・クライシス · 1. GOMAXPROCS の謎を解く · 2. 圧力下でのガベージコレクション · 3. GC ポーズとレイテンシ · 4. コンテナ・デバッグの実践ワークフロー

Go in Containers - この記事は連載の一部です
パート 3: この記事

関連記事

圧力下でのガベージコレクション
·851 文字·4 分
Go Kubernetes Containers Garbage-Collection Memory
GOMAXPROCS の謎を解く
·870 文字·5 分
Go Kubernetes Containers Scheduler Performance
AIエージェントのタスク管理、GitHub Issuesでやってみた
·678 文字·4 分
Ai Go Automation Github Devops
配管地獄を止める:`bs` を作っている話
·80 文字·1 分
Go Devops Build-Systems Bs Engineering
そのプライマリキーがボトルネックだ(スケーリングじゃ直らない)
·701 文字·4 分
Postgresql Performance B-Tree Uuid Database-Design