こんにちは。Backend Enablement Team のエンジニアの @goccy です。
この記事は、Merpay & Mercoin Advent Calendar 2025 の7日目の記事です。
時は今から4ヶ月ほど前の8月下旬、とても暑い日でした。珍しくチームの On Caller の PagerDuty がアラートを上げました。内容は Gateway からあるマイクロサービスへの呼び出しが突然 Timeout するようになり、gRPC の Deadline Exceeded が急増しているというものでした。対象のマイクロサービスは gRPC Federation を利用した BFF ( Backend for Frontend ) で、基本的にはさらに後ろのマイクロサービスにプロキシするだけの単純なサービスです。少し調査すると、該当の gRPC メソッドには Timeout が設定されていなかったため、Gateway 側で設定した Timeout ( 30秒 ) を超過した際に、Gateway 側でリクエストをキャンセルするタイミングで出ているエラーだとわかりました。この間、BFF 側でエラーが発生していないにもかかわらず Goroutines は増え続けていることから、リクエストが処理できずにサーバー上で滞留しているような状況だと推測できました。しかし、それ以上の調査が困難なことと、問題が起きているのが一部の Kubernetes Pod だけだったため、該当の Pod を再起動することを試したところ、無事解決に向かいました。その日は営業時間が終了間際だったこともあり、もやもやしたものを抱えつつ、いったん解散して帰途につくことになりました。
このときはまだ、これから長い闘いが待っていることをチームの誰も知る由もありませんでした。
サービス間の関係図
それから二日後、先日の問題の原因究明もろくにできていないような状況で、再びアラートが上がりました。しかし今回は前回とは別のサービスで、かつ gRPC Federation を利用していました。現象は前回同様、突然該当のサービスの特定の Pod だけ Goroutines が急増し応答しなくなるという問題で、Pod を作り直すと改善するという現象も同様でした。
立て続けに gRPC Federation を利用する複数のサービスで同様の問題が起こったため、原因が gRPC Federation 側にありそうだという線が濃厚になってきました。これはとてもまずい状況です。gRPC Federation を利用するサービスは 20 を超えます。
突如として暗雲が垂れ込めます。この日から、チーム総出でこの問題に対処するようになりました。
Lock 範囲の最小化
まず、該当のサービスの直近のリリースに含まれる gRPC Federation の変更点などを調査しましたが、こちらは特に怪しいものはないという結論に至りました。次に、リクエストが滞留し続けることから、gRPC Federation 側で取得している Lock の待ち時間が長すぎたり、Dead Lock しているケースがないかを疑いました。該当のサービスでは Cloud Profiler を導入しており、その結果から Lock 待ちをしているスレッドが大量にあることがわかりました。Lock 箇所として複数の候補がありましたが、それらを Claude Code を使ってプロファイリング結果を参照しながら議論したところ、いずれも Dead Lock でないこともわかりました。次の可能性として、Lock を解放するまでの時間が長く、Lock を解放するよりも Lock の待ち行列に加わるスレッドの方が多くなり、結果 Goroutines が増え続けている可能性を考えました。そこで、まずは Cloud Profiler が挙げた Lock 箇所のうち、Lock 範囲を最小化することで不必要に長く Lock を取得している箇所をなくしました。( 該当のPR )
しかし数日後、また Goroutines が急増しアラートが上がりました。この時点から、一日に3〜 5回程度不定期にアラートが鳴り続けるようになってしまい、Pod を再起動するだけとはいえ、On Caller の負担が顕著に増えました。ただ、Lock 範囲を狭めたことで、Lock 待ちをしている箇所のほとんどが gRPC Federation のプラグインを利用している箇所であるとわかりました。
gRPC Federation のプラグインアーキテクチャ
ここで、以降の説明を理解しやすくするために gRPC Federation のプラグインアーキテクチャについて解説します。gRPC Federation 自体の詳しい説明は私が以前書いた別記事をご参照ください。
簡単に説明すると、gRPC Federation は Protocol Buffers 上で記述できる型推論付き静的型付け言語であり、式の評価には CEL( Common Expression Language ) を利用しています。 OSS として開発しているため、Protocol Buffers 上で記述する CEL 式の中でドメイン固有のロジックを利用することは通常できません。例えば認証処理を例にとると、gRPC の metadata から 認証用の JWT を取り出してパースし、得られた値をバリデーションしたり、さらに別の値を取得するような処理は CEL の表現力の範囲を超えています。ですが、こういった処理は gRPC Federation を利用するすべてのサービスで必要になる共通処理でもあります。
gRPC Federation ではこのような要件のために、CEL 式の中で利用できる API を独自に定義し、その実装を Go で書いて WebAssembly に変換して利用するプラグインシステムを用意しています。
Go でプラグインシステムを提供する場合、WebAssembly を利用するのが最善であることは、先日 Go Conference 2025 で発表してきた ( Go で WebAssembly を利用した実用的なプラグインシステムの構築方法 ) ので、詳しくはそちらを参照して欲しいのですが、重要なこととして、WebAssembly を利用する場合に次のような制約があることを知っておく必要があります。
- WASI P1 という仕様に沿って動作するが、P1 の段階ではスレッドの仕様は存在しない
- スレッドの仕様がないため、必ずシングルスレッドで動作する
- WebAssembly を動作させるために作るインスタンスは、起動するだけで数十MBのメモリを消費するため、インスタンスを無制限に作るようなアーキテクチャは採用できない
これらの制約のため、gRPC Federation ではプラグインを評価する際、gRPC Service ごとにプラグインに対する WebAssembly インスタンスを一つだけ作成し、評価の前後で Lock を取得して直列に処理します。これはつまり、サーバーに対してどんなに並行にアクセスしても、プラグインの処理の段階では直列実行になることを意味しています。
Cloud Profiler の結果、このプラグイン評価時に取得する Lock 待ちが大量に発生していることが原因だとわかりました。
また、以降ではプラグインの評価に際して、WebAssembly ランタイムを動かすGo 側をホスト、プラグイン側をゲストと呼称して説明します。
問題の再現に挑戦
具体的な原因がわかってきたところで、プラグインの評価を高頻度かつ大量に行うことで問題が再現するかを試し始めました。ローカルで立ち上げたサーバーに対して高負荷な状況を作ったり、開発環境にデプロイしているサーバーに対してリクエストするなどさまざまなアプローチをチーム総出で試しましたが、問題が起こった gRPC メソッドに対して 1000rps を超える負荷を 30分近くかけ続けても再現には至りませんでした。
ここで、問題を再現することが難しいことが分かったため、問題発生時に本番環境で取れる情報を増やす方向も考え始めました。具体的には対象のサービスに pprof による計測用のエンドポイントを仕込んでおき、問題が起きたときに対象の Pod のサーバーに対してプロファイリングを実行することで、 Cloud Profiler ではわからない情報をとれるようにしました。
pprof による調査
pprof を仕込んだ翌日、問題が再発しました。今回は対象の Pod を再起動するのではなく、Pod を Kubernetes Service から切り離し、切り離したサーバーの pprof のエンドポイントにリクエストを送ることで各種データを取得しました。
取得した結果を対象に、例えば go tool pprof -traces を実行すると、計測時に動いていたすべての Goroutines をスタックトレース付きで把握することができるのですが、プラグイン関連のスタックトレースを見ると、プラグイン評価に際してホストとゲストそれぞれが相手からのリクエストを待っている状態になっていました。これはありえない状況です。ホストは正しくゲストに要求を伝えたと思っているが伝わっていない、もしくはその逆の現象が発生している可能性があります。
それぞれが同時に相手からの要求を待ち受けているということは、永久にその要求は満たされません。そのため、デッドロックのような状況になってプラグイン評価が永遠に行われず、プラグイン評価は直列に動作するため、サーバーの処理が停止してしまう事態になっていることがわかりました。
しかしここから調査が難航します。そもそもなぜこのような事態になっているかがわからなかったのと、問題が起こるたびにプロファイリングをしても結果が毎回同じ内容だったため、新しい情報が得られませんでした。ローカルでも引き続き再現しません。
そこで、プラグインインスタンスに何らかの不調が起きて、突然ホストとゲスト間の疎通ができなくなると仮定し、ホストとゲスト間のメッセージのやりとりに利用するメモリの読み書き処理でエラーになった場合は、あらかじめ作っておいたバックアップインスタンスにフォールバックするような仕組みを作成しました ( https://github.com/mercari/grpc-federation/pull/327 )。もしどこかでエラーが返るようであれば、インスタンスをリフレッシュすることで復帰できるはずです。
しかし結果は期待とは異なり、エラーが発生することもなく、予兆なしに突然問題が発生してしまいました。
GC を疑い始める
プラグインを評価する際、ホストからゲストへのリクエスト方法は大きく2通り存在します。
一つは認証処理の例で説明したような通常の API リクエストです。もう一つはGCの実行でした。
WebAssembly ランタイムではアロケーション戦略としてリニアメモリを採用しており、メモリが足りなくなったら倍のメモリを確保して対処します。ですが、メモリが十分でも確保した範囲を縮小することはしません。つまり、GC が走るタイミングが遅れるほど、メモリが不必要に多く確保されてしまうことになります。これを防ぐため、プラグイン側で細かく GC を実行する必要があり、gRPC Federation では定期的にホストからゲストに対して、強制的に runtime.GC() を実行するように要求する戦略をリリース初期から1年以上行ってきました。
このアーキテクチャをふまえ、本番環境でしばらく運用した際にエラーなく突然問題が起こることから、GC をトリガーした際に問題が起こるのではないかという仮説を立て、ホストからの GC 呼び出し処理をなくすことで、事態が好転するのではないかと考え始めました。仮に GC が関係なかったとしても、ホストからゲストにリクエストを投げる回数自体が減るため、問題が発生する頻度が下がるのではないかという期待もありました。
トレードオフとして、プラグイン側で GC が走る頻度が減るため OOM ( Out Of Memory ) になるリスクは上がりますが、まずはホストからゲストへの GC 要求をやめて様子を見てみることにしました。
事態が好転し始める
GC の経路を削除した後、アラートが上がる頻度が目立って減りました。しかし、予想通り OOM が発生してしまったのと、頻度がゼロにはなっていないため、根本対策にもなっていません。
プロファイリングしても相変わらず同じ結果でした。
しかし、事態が今までと変わったことから、問題の切り分けのためにプラグイン側で自動で走る GC を疑ってみることにしました。プラグイン側で走る自動GCを GOGC=off 環境変数を指定することで止め、強制 GC のみで運用する方法です。このとき、より実装をシンプルにするため、今までホスト側で GC の終了を待っていなかったのを同期的に待つようにしました。補足として、今まで GC の終了を待っていなくて大丈夫なのかと疑問に思った方がいるかもしれませんが、ゲスト側で強制GCの場合を特別扱いして処理しているので非同期にすること自体は問題ありません。
この状態でしばらく運用したところ、問題が発生する時は、スタックトレースから必ず強制GCの経路になっていることがわかりました。つまり、ホストから強制GCを実行したところ、その結果が返らずに停止しているということになります。
ホスト・ゲスト間の通信方法の改善
突然 runtime.GC() から処理が返ってこなくなるとは考えにくかったので、GC が走った影響で、ホストとゲスト間の通信に利用する何かが壊れたと推測しました。そこで、両者の通信方式をよりシンプルなものに変更することで GC の影響を減らすことができるのではないかと考え、今まで利用していた STDIO を使った通信方法をやめ、ホスト関数と Go のチャネルを利用した通信方式に変更し、すべてをホスト上で行う標準的な Go のチャネルを介した処理に変更しました。
https://github.com/mercari/grpc-federation/pull/331
https://github.com/mercari/grpc-federation/pull/333
この処理は Go Conference 2025 で紹介した際のホスト・ゲスト間の通信処理を改善したものなので、興味のある方は見てみていただければと思います。
別件で、プラグイン上でネットワークソケットを扱うために導入した wasi-go というライブラリも疑い、ネットワークソケット関連の syscall 以外を wazero が提供する枯れた実装に置き換えようともしましたが、wazero がファイルシステムまわりの API を private にしているために、 wasi-go 側で作った ソケットディスクリプタ を wazero 側に伝える方法がなく断念しました。
さて、この改善を行ったことで事態がより進展すると思われましたが、問題は収束せず、プロファイリングすると、ホストとゲストそれぞれでチャネルの受信処理でブロックしているという結果になりました。ただし、いずれも強制GCの結果待ちでした。
ログを仕込む
今回の問題は本番環境で長時間運用しなければ発生しなかったため、コストの面からデバッグログを仕込むことを躊躇っていました。しかし、これ以上原因をしぼりこむことができなかったため、遂にログを追加することにしました。あわせて Trace も追加しました
気をつけたこととして、問題が発生したらできるだけすぐにデバッグログを無効にしたかったため、環境変数を有効にしたときだけログを有効にするような Feature Flag 方式を採用し、環境変数の変更を巻き戻せばすぐに元に戻せるようにして運用しました。
ログを有効にして計測した結果、ゲストがGC 実行の要求を受け取ったというログは見つかりましたが、結果を送信するというログがなかったため、ないだろうと考えていたGC実行中にハングしている可能性が濃厚になりました。
また、ログを仕込んだ結果、ホストとゲストでどちらも受信待ちになっていたと思っていた不可思議な現象は、実は別のプラグインインスタンスだったことがわかりました。つまり、ホスト側とゲスト側のスタックトレースは、それぞれ別のインスタンスのものを表示していたのです。先に説明した通り、gRPC Federation は gRPC Service ごとに作るプラグインインスタンスは一つですが、 同一プロセス上で動く gRPC Service が複数ある場合はインスタンスも複数になります。このことを考慮できていなかったのが悔やまれます。しかしこれで、問題がデッドロックではなくGC実行中のハングに収束したためとてもシンプルになりました。
インスタンスの自動復旧対策
気づくと10月も半ばに差し掛かっていました。振り返ると8月下旬から数えて2ヶ月近く格闘していたことになります。
ですが問題が明確になったことで、取れる策も具体的になりました。GC実行中に処理が返らなくなることから、まだその原因はわからないにせよ、ワークアラウンドを実装することはできます。強制GCにタイムアウトを設け、タイムアウトした場合はインスタンスが壊れたと判断し、前に実装していたインスタンスをバックアップに切り替える仕組みを使って自動的に復旧することができるはずです。
ついでに、インスタンスを切り替える際にログも出力してみます。無事復旧しているならばログが出るはずです。
この対応を行ってから、数日間様子を見ましたが、仕込んだログは定期的に出力されつつ、Goroutines が急増することもなくなりました。
ひとまず、ワークアラウンドはうまく動いていそうで、障害対応が落ち着いたといえる状態になりました。
このとき行った実装はこちらです
根本原因が判明
障害対応が落ち着いたので、今まで得られた情報からより再現しやすい環境で調査を続けたところ、長時間動作させる中でローカルで再現できるようになりました。依然として再現することは難しかったですが、それでも再現できたことは大きく、詳細なデバッグログを仕込んで複数回実行する中で、 ネットワークソケットを利用するために導入した wasi-go というライブラリの PollOneOff syscall 内で呼び出している unix.Poll から処理が返ってこなくなることがわかりました。デバッグログの結果から、どうやら通常は 0 になるはずの unix.Poll に渡している timeout 値が異常値(負数)になっており、永久にくることのないイベントを待ってブロッキングする挙動になっていることがわかりました。また、PollOneOff と GC に因果関係があるかを調べるために Go 本体のソースコードを追ってみると、GC のシーケンスで PollOneOff が呼び出される経路があることもわかりました。
この問題を修正したときのPRはこちらです。
※ ライブラリは私が作ったもののように見えますが、実際には fork したものを使っています。
この修正を適用したあと、仕込んだインスタンス切り替え時のログは出力されなくなり、無事問題が解決しました。問題発生から2ヶ月ほどのことで、あの暑かった夏から少し肌寒くなってきていました。
反省点
あらためてプロファイリング結果を思い返すと、実は PollOneOff のスタックトレースは一番最初に計測したプロファイリング結果に含まれていました。勘がよければ、最初の時点で PollOneOff が原因だと気づくこともできたのです。
PollOneOff は epoll のようにファイルディスクリプタに対するイベントを監視する WASI 用の syscall で、スタックトレースは最初から目に入っていましたが、初期の実装ではホストとゲスト間の通信に STDIO 方式を採用していたため、通信時に利用する標準入出力のイベント待ちで呼び出されているのかと勘違いしていました。また、wazero ( WebAssembly ランタイム ) 側で特別に別スレッドでイベント待ちをしているのかとも予想しており、あまり気にしていなかったのが悔やまれます。
冷静に考えると、あとで Go のチャネルを利用した通信方式に切り替えてもスタックトレースに現れていたのはおかしいし、シングルスレッドアーキテクチャなのに別スレッドでイベント監視しているのもおかしいので、先入観で判断してはいけないと改めて気付かされました。
逆に、最初からプロファイリング結果に答えは書かれていたので、pprof が大事だとも言えます。
振り返り
本番環境でしか問題が起こらない場合、問題のある Pod を単に再起動するのではなく、サービスから切り離してプロファイリングするのは非常に重要なフローでした。
pprof は実行時にしか負荷がかからないので、本番用のビルドでも関係なく pprof の計測エンドポイントを持っておいた方がいいという気づきも得ました。
また、ちょっとしたことですが、デバッグログを無効化するために実装を巻き戻して image を作り直し、 hotfix を deploy する方法だと時間がかかってしまうので、環境変数によってデバッグログの出し分けを制御できたのは良かったです。
今回の対応では、問題のあるPodをサービスから切り離した後、pprof によるプロファイリングをメインに対応してきましたが、実はもうひとつ試したかったこととして、 Delve でのサーバープロセスへのアタッチによるデバッグがありました。しかし、いくつかの制約により実施には至らず、もし実行できていれば unix.Poll 時に timeout 値が変な値になっていることに気付いたかもしれないため、今後の課題です。
メルカリグループ全体の課題として、プロファイリング結果や Core ファイルなどを永続化する手段を標準化していないため、仮にそれらの情報をディスクに書き出したとしても、Pod が消えると情報が消えてしまう問題があります。Go 1.25 から入った Flight Recorder などを効果的に利用するためにも、解析情報を Pod の外に退避させ、デバッグ時に参照できるような仕組みを構築することが重要だと考えています。
今回修正を加えた https://github.com/goccy/wasi-go は、https://github.com/dispatchrun/wasi-go を fork したものなのですが、fork 元のメンテナンスが停止していること、自分の方のライブラリでは今回の修正対応以外にも TLS 対応や exec.Command 対応など、実際のユースケースに応じたさまざまな改善が入っているので、これから Go が WASI P2 に対応するまでの間で WebAssembly を使いたいと思っている方には強い味方になってくれるはずです。ぜひご利用ください。
最後に、今回 Claude Code にプロファイリング結果の分析などの壁打ち相手になってもらいましたが、AI は答えを出そうとするあまり誤った答えを平気で出してくるので、嘘を嘘だと見抜く力が必要だと強く感じました。
明日の記事は fenomasさんです。引き続きお楽しみください。
