HN 日本語サマリー

← 一覧へ戻る
プログラミング

Goのガベージコレクタ、スワップが原因で40msの一時停止を引き起こす

A 40ms Go garbage collector pause caused by swap (frn.sh)

22 pointsby shellpipe6 コメント

要約

本記事は、本番環境でスワップを有効にした際に発生しうる、Goのガベージコレクタ(GC)における予期せぬ長時間停止(40ms)について解説しています。GCが参照するメタデータページがスワップアウトされた場合、GC実行時にディスクI/Oが発生し、これが「Stop-the-world」ポーズを著しく遅延させる原因となります。この問題はアプリケーションの応答性に深刻な影響を与える可能性があり、筆者はそのメカニズムと影響、そして回避策について詳細に分析しています。

全文翻訳

これは、メモリの急増を吸収するために本番環境でスワップを実行することにした際に、私がほとんど額を叩きそうになった経験を共有するために書いています。私は2つのプロセスを持つcgroupを持っていました。1つはio.ReadAllとproto.Unmarshalを呼び出し、ブロブを作成してからグラフ構造(Goのアロケータによってスキャン対象としてマークされている)を作成するGoプロセスです。もう1つのプロセスは、ほとんど静かなHTTPサーバーです。コレクタが実行されるたびに、そのスキャンされたスパンをポインタごとに読み取り、どうするかを決定します。そこで私は考えました。「メモリプレッシャーの下では、カーネルはページをスワップデバイスに追い出すだろう。しかし、追い出しはプロセスごとではなくcgroupごとだから、両方のプロセスのページが追い出されることになる。これはカーネルとガベージコレクタの間でスワップインとスワップアウトの悲しいダンスになる可能性は小さいだろう。」私は間違っていました。これを実験している間に、私を傷つける可能性のある問題を発見しました。Goのガベージコレクタは、ヒープの外にある(解放されない領域である)メタデータを、Stop-the-worldの一時停止中に読み取ります。そして、そのメタデータがスワップにある可能性があります。私はHetznerのボックスで、カーネル6.8とMGLRUを有効にしてモック実行を行いました。これらの実験に関するすべてのもの(プロット、モックアロケータ、bpfスクリプト、pythonスクリプトなど)は、ここで見つけることができます: https://github.com/frnsimoes/go-gc-swap-cost。中央値の一時停止は約51マイクロ秒でした。メタデータがNVMe上にある場合、最悪の一時停止は40ミリ秒でした。その40ミリ秒がどこに行ったのかを確認するために、世界が停止している間にページフォールトをカウントする小さなbpfスクリプトを書きました。これが最悪のケースでした: 39902マイクロ秒、その間のフォールトは228、フォールトで39013マイクロ秒。40ミリ秒のうち39ミリ秒は228回のページフォールトに費やされました。これらのフォールトはGCのブックキーピング内で発生しました: // addr2line 出力 0x42e5c8 runtime.(*spanSet).reset /usr/local/go/src/internal/runtime/atomic/types.go:194 0x4219de runtime.finishsweep_m /usr/local/go/src/runtime/mcentral.go:71 0x4629cf runtime.gcStart.func2 /usr/local/go/src/runtime/mgc.go:724 0x46dd8a runtime.systemstack /usr/local/go/src/runtime/asm_amd64.s:518 0x4169dc runtime.gcStart /usr/local/go/src/runtime/mgc.go:722 0x4276a4 runtime.nextMarkBitArenaEpoch /usr/local/go/src/runtime/mheap.go:2481 0x421a65 runtime.finishsweep_m /usr/local/go/src/runtime/mgcsweep.go:268 0x4629cf runtime.gcStart.func2 /usr/local/go/src/runtime/mgc.go:724 0x46dd8a runtime.systemstack /usr/local/go/src/runtime/asm_amd64.s:518 0x4169dc runtime.gcStart /usr/local/go/src/runtime/mgc.go:722 これは潜在的な障害モードです。GoのGCは、スイープ終了(sweep termination)を実行するときと、マーク終了(mark termination)を実行するときの2つの時点で世界を停止させる必要があります。テストでは30分間に312回のそのような一時停止がありました。では、なぜこれが起こるのかというと、ランタイムはそのページを割り当てます。それらは解放されず、再利用されます。これらのページはGCサイクルで読み込まれます。カーネルはアクセス頻度の低いページをスワップに送るため、GCが実行され、世界を停止し、それらのページを読み込もうとしますが、ここでメジャーページフォールトが発生します。カーネルはPTEを読み取り、do_swap_pageを呼び出し、新しいフレームを見つけ、それをcgroupに割り当て、ページを読み込み、ディスクへのI/Oを送信し、ディスクを待ってからメモリに戻す必要があります。これは、簡潔に言うと、そのような処理です。これらの40ミリ秒は、最初は無害に見えます。しかし、私たちはStop-the-worldの一時停止について話しています。その40ミリ秒はすべてが停止したことを意味します。Goの用語では、すべてのPが停止したため、例えば、goroutineがI/Oを待っていた場合、その一時停止中にI/Oが返ってきても、それを処理するものがなくなります。40ミリ秒は中央値の一時停止の800倍です。テスト中、メモリの急増ごとに2〜3回発生します。それは非常に多いです。そして、別のことに気づきました。通常3〜5ミリ秒かかる511 KiBのメッセージのビルドが、NVMe上では105ミリ秒、Hetznerのネットワークボリューム上では903ミリ秒に跳ね上がりました。メッセージあたり、これはメタデータの一時停止よりもコストがかかります。しかし、その価格を支払うのは割り当てを行っているgoroutineだけなので、少なくともそれは局所的であり、メタデータの一時停止のようなグローバルなものではありません。その時間がどこに行ったのかはまだ確認していませんが、それでもここに言及したいのは、それもあなたが支払うことになる別のコストだからです。いずれにせよ、Chris Downの意見に同意します。スワップは悪ではありません。しかし、ガベージコレクションとはうまく機能しませんでした。そして、本番環境では、私は多くのものを収集しています。 更新、9月14日。Go 1.26のGreen TeaガベージコレクタがGCがメタデータを読み取る方法を変更したかどうか尋ねられました。測定したところ、影響は無視できる程度でした。これらの実験に関するすべてのもの(プロット、モックアロケータ、bpfスクリプト、pythonスクリプトなど)は、ここで見つけることができます: https://github.com/frnsimoes/go-gc-swap-cost ↩︎