Ruby をアップデートしたらスケジューラのバグを踏んだ話

Ruby をアップデートしたら スケジューラのバグを踏んだ話 三軒家 佑將 ゲームサービス事業本部 開発運営統括部第三技術部 サーバーグループ © DeNA Co., Ltd. 1

目次 1 Sakasho2p について 2 Ruby をアップデートしたらスケジューラのバグを踏んだ話 3 Take Home Message © DeNA Co., Ltd. 2

自己紹介 三軒家 佑將 ゲームサービス事業本部開発運営統括部第三技術部サーバーグループ ● 2019年新卒で入社 ● モバイルゲームのサーバーの開発チーム ○ Sakasho2p 基盤整備やコードレビューなどをやっています ● ● © DeNA Co., Ltd. 最近の趣味：将棋 ○ 昨日初めて将棋ウォーズで1勝しました 🎉 3

Sakasho2p について © DeNA Co., Ltd. 4

1 5 Sakasho2p とは ● 大規模グローバル配信モバイルゲーム向けのサーバー ○ Ruby on Rails 製 ○ MySQL / Elasticsearch / Redis などの、よくある技術スタック ■ ○ Q4M などの古代技術も一部使われている 高負荷 && 高品質が基本 ● 機能開発のかたわらで、基盤の刷新を行っている ○ Jenkins から GitHub Actions への乗り換え ○ デプロイの高速化 ○ Ruby / Rails のアップデート ■ © DeNA Co., Ltd. 今日は Ruby 3.4.1 へのアップデートで発生した問題について話します 5

Ruby をアップデートしたら スケジューラのバグを踏んだ話 © DeNA Co., Ltd. 6

1 CI に問題発生 ● Ruby を 3.4.1 にアップデートしたところ、CI がたまにタイムアウトするようになった ● 調べてみると、以下のような状況に陥っていることが判明 © DeNA Co., Ltd. ○ rspec のプロセスの CPU 使用率が 100% に張り付いている ○ メモリ使用量は鰻登りとなり、OOM killer に処されてやっと停止する状況。 7

2 調査 ● 原因が皆目不明なため、さまざまな調査手法を試した ○ strace でシステムコールを観測 ■ ○ GC の統計情報を確認 ■ ○ © DeNA Co., Ltd. よくわからず、調査を断念 rspec のオブジェクトが大量に allocate されていることはわかったが、原因は不明 最終的には sigdump が決め手となった 8

3 sigdump とは ● https://github.com/fluent/sigdump ○ プロセスを再起動することなく、さまざまな情報を取得できる gem ○ 使い方 ○ ■ Gemfile に sigdump を追加 ■ Ruby のプロセスに $ kill -CONT <pid> を打つ ■ /tmp/sigdump-<pid>.log に dump が出力される dump から取れる情報 ■ 全スレッドの stacktrace ● ■ クラスごとの、allocate されたオブジェクトの数 ● © DeNA Co., Ltd. 各スレッドが、どの処理を実行中なのかわかる どのクラスのインスタンスがどのぐらい allocate されたのかわかる 9

• https://github.com/fluent/sigdump

4 暴走しているプロセスの状態 ● sigdump からわかったこと ○ メインスレッドは Dir.glob(‘*’) で停止している ○ メインスレッドの他に、sshkit が起動した謎のスレッドが存在する ○ rspec 内部のオブジェクトが大量に allocate されている 🤔 © DeNA Co., Ltd. 10

暴走しているプロセスの状態 4 ● sshkit のスレッドとは何者か？ ○ sshkit: ssh 関連の gem ○ ssh のコネクションを定期的にチェックし、 接続が切れていたら消すためのスレッド すごく簡略化したコード ● rspec 内部のオブジェクトとは何者か？ ○ allow(hoge).to receive(:fuga) みたいなことをして、 fuga が呼ばれた時に生成されるオブジェクト ○ © DeNA Co., Ltd. fuga が N 回この引数で呼ばれた、みたいな情報を保持してるぽい 11

なぜ rspec が暴走するのか 5 ● テストコードの中に allow_any_instance_of(Object).to receive(:sleep)している箇所があった ○ ● Ruby プロセス全体で sleep がスタブされる バックグラウンドスレッドで先ほどのループ処理が猛烈な勢いで回転する ○ CPU 使用率が 100% に張り付く ○ ループごとに rspec 内部のオブジェクトが ここが停止 しなくなる 生成され、メモリ使用量が鰻登りとなる ● Ruby においては、同時に一つのスレッドしか動けない(GVL) ● しかし、メインスレッドで動いているテストが進行すれば そのうち sleep のスタブが解除されて解決するはず ● Ruby 3.4.1 からはテストが進行しなくなった ← ？？？ © DeNA Co., Ltd. 12

原因: Dir.glob 内部の最適化 6 ● Ruby 3.4 系には、Dir.glob(‘*’) が頻繁に GVL を手放すような修正が入っていた ○ https://github.com/ruby/ruby/pull/11147 ○ NFS などの遅いファイルシステムで Dir.glob(‘*’) を実行した時に、 適切に GVL を解放して他のスレッドをブロックしないことを意図したもの ● テストの中に、 Dir.glob(‘*’) を実行するコードが存在していた ○ こいつが頻繁に GVL を手放すので、テストが全然進行しない ○ メインスレッドが GVL を獲得して処理をちょっとだけ進める → すぐにGVLを解放してバックグラウンドスレッドの処理が走る → メインスレッドが GVL を獲得して処理をちょっとだけ進める → すぐにGVLを解放してバックグラウンドスレッドの処理が走る → メインスレッドが GVL を獲得して処理をちょっとだけ進める … © DeNA Co., Ltd. 13

• https://github.com/ruby/ruby/pull/11147

7 実際にスレッドの様子を見てみよう Ruby のスレッドの動作の様子や GVLの状態などが観察できる gem https://github.com/ivoanjo/gvl-tracing © DeNA Co., Ltd. 14

• https://github.com/ivoanjo/gvl-tracing

8 再現コードを gvl-tracing に突っ込んでみる Main Thread は wants_gvl 状態 再現コード ↓拡大 ずっとThread 1 が running 一瞬 running になって すぐに waiting に戻ってる © DeNA Co., Ltd. 15

Ruby のバグチケットを起票 9 ● Ruby のデグレと考えられるので、バグチケットを起票 ○ ● https://bugs.ruby-lang.org/issues/21119 Ruby 3.3.5 では2秒程度で完了するコードが、 Ruby 3.4.1 では120秒ほどかかることを示した ○ ● 50倍ほど遅い スケジューラをもっと賢くしたいという 結論になっているようです © DeNA Co., Ltd. 16

• https://bugs.ruby-lang.org/issues/21119

Sakasho2p での対応 10 ● allow_any_instance_of(Object).to receive(:sleep) しているテストをコメントアウト ○ 例外発生時の exponential backoff retry のテストだった ○ 直近で修正が入る予定がないのと、手動でのテストも可能であることから コメントアウトしてもリスクが低いと判断 ● 将来の Ruby 側のデグレに備え、ruby/head でも CI を回すようにした ○ © DeNA Co., Ltd. Ruby 側でデグレが発生したときに迅速にフィードバックすることが可能になった 🎉 17

Take Home Message © DeNA Co., Ltd. 18

Take Home Message 1 ● allow_any_instance_of を使うのは避けよう ○ 特に allow_any_instance_of(Object)の危険度は高い ● sigdump は便利 ○ ダンプファイルには大量の情報が出力されるので、見落としがないように気をつけよう(1敗) ○ メモリ情報が出力されていることに気が付かず、無駄に GC 周りのログ出力処理を実装したりしてしまった ● 問題発生時に原因を深掘りしていくと、思わぬ結論を掘り当てることがあって楽しい ○ 単にテストをコメントアウトするだけでなく、 Ruby 側の問題までたどり着けたのはよかったと思ってます © DeNA Co., Ltd. 19

© DeNA Co., Ltd. 20