Copilotのメモリリーク問題

 (stevenharman.net)
1 ポイント 投稿者 GN⁺ 2024-05-12 | 1件のコメント | WhatsAppで共有
  • 10年ものの Rails本番アプリの web Dyno メモリがデプロイ中に急増し、400〜500 req/s の継続的な負荷とピーク時には数千 req/s を処理するサービスだったため、迅速な緩和が必要だった
  • Herokuでメモリ上限に近いDynoを再起動し、直近3日間のコード・メトリクス変更を戻したが、メモリリークは続いた
  • SidekiqとDelayed::Jobは正常な一方で、Puma workerの一部だけが肥大化するパターンが見られ、特定のトラフィック種別との関連が疑われた
  • rbtrace、ObjectSpace、heapy、sheap、reapでヒープを追跡した結果、Pumaのリクエスト処理スレッドが ActiveSupport::Notifications::Event の @children 配列を通じて32,067個のオブジェクトと1.9GiBのメモリを保持していた
  • 細工されたクエリパラメータがBugsnagのURLクリーニング処理で URI::InvalidURIError を引き起こしており、短期対応はBugsnagのアップグレード、長期対応はRailsのアップグレードだった

運用中のRailsアプリでリークが始まる

  • 対象は10年ものの Railsアプリで、実際に売上を生み出している本番サービスだった
  • 平常時の継続負荷は400〜500 req/sで、ピークは毎秒数千リクエストまで上がる
  • 通常のデプロイフロー中にメモリスパイクが始まり、Pagerのアラートが発生した
  • Heroku上で動いていたため、Dynoごとのメモリ値を基準に状態を見た

障害緩和はDyno再起動から始まった

  • 現象は単なるメモリ膨張（bloat）ではなくリークのように見え、暫定的な解決策はプロセス再起動だった
  • 普段は1日に複数回のデプロイで web インスタンスが再起動されていたが、メモリ上限に近づいたDynoは手動で再起動した

疑わしい変更を戻してもリークは残った

  • 最初の大きなスパイクの直前からさかのぼり、3日分のコード変更を監査した
  • 関連していそうな変更は3つあった
    • development モードでRailsのコードリロードによりメモリリークを起こす変更
    • 特定のリクエストフィルタリング中にRedis呼び出しが意図より多くなる変更
    • より多くのデータベース呼び出しと ActiveRecord インスタンスのロードを引き起こすN+1型の変更
  • 前の2つの変更は修正し、3つ目の変更はロールバックしたうえで1つずつデプロイしたが、リークは続いた
  • Ruby言語メトリクスとPuma pool使用量メトリクスを収集するためのツール変更も戻したが、メモリ増加は止まらなかった

リークパターンは特定のトラフィックを示していた

  • リークは web Dynoでのみ発生し、SidekiqとDelayed::JobのDynoは正常に見えた
  • すべての web Dynoが常にリークしていたわけではなかった
    • 数時間にわたって、長時間稼働するWebプロセスのように比較的平坦なメモリ使用量を示す
    • その後ある時点で、1つ、一部、または全Dynoがリークし始める
  • Pumaはクラスターモードで実行され、Dynoごとに8 vCPUに対して12 worker processを使用していた
  • 1つのDyno内でも、12個のworkerのうち一部だけがほぼすべてのメモリを使う場合があった
  • OpenTelemetry Tracesはサンプリングが強く、特定のリクエスト種別と特定のDynoを結びつけるのは難しかった。また、サンプリングされないログとの相関分析もツール上は容易ではなかった

ヒープダンプを収集する手順

  • 実行中のRubyプロセスにアタッチするために rbtrace を使用した
  • rbtrace はプロセスにロードされている必要があるため Gemfile に含め、環境変数でロード有無を制御した
gem "rbtrace", require: String(ENV.fetch("FEATURE_ENABLE_MEMORY_DUMPS", false)) == "true"
  • Herokuでは heroku ps:exec でリーク中のDynoにSSHトンネルを開き、ps でRubyプロセスをRSS基準でソートした
ps -eo pid,ppid,comm,rss,vsz --sort -rss | grep ruby
  • web Dynoでは同じ PPID を持つプロセス群がPuma workerであり、最も多くのメモリを使っているworkerの PID を対象にした
  • メモリ割り当て追跡は ObjectSpace.trace_object_allocations_start で有効にし、性能・メモリ・CPUに影響する可能性がある
DUMP_PID=<pid>
rbtrace --pid="${DUMP_PID}" --eval="Thread.new{require 'objspace';ObjectSpace.trace_object_allocations_start}.join"
  • ヒープダンプは ObjectSpace.dump_all で /tmp に生成し、数時間実行されたリークプロセスではJSONファイルが5〜6GiBまで大きくなった
rbtrace --pid="${DUMP_PID}" --eval="Thread.new{require 'objspace'; GC.start(); io=File.open('/tmp/heap-${DUMP_PID}.json', 'w'); ObjectSpace.dump_all(output: io); io.close}.join" --timeout=600
gzip "/tmp/heap-${DUMP_PID}.json"
  • Herokuでは heroku ps:copy でダンプをローカルに持ってきて、heapy でretained memoryを見るには少なくとも3つ程度のダンプを収集した
  • 作業後は割り当て追跡を止め、ダンプを削除するかDynoを再起動した

ヒープ分析で1.9GiBを保持したThreadが明らかに

  • heapy のretained memoryレポートと sheap diffだけでは出発点を見つけるのが難しかった
  • Rubyヒープダンプの参照グラフを分析・可視化する reap でフレームグラフを生成した
  • フレームグラフはRuby GC視点のrootから下位オブジェクトへ続く参照を示し、より多くのメモリを保持するオブジェクトほどセルが広く表示される
  • 3つ目のヒープダンプで、ある Thread が1.9GiBのメモリを保持していた
  • 実際には下位の Array が32,067個のオブジェクトを参照し、1.9GiBを維持していた

sheapで参照パスをたどる

  • 最新の main ブランチの sheap を使い、2つ目と3つ目のダンプを比較した
  • ダンプサイズが6GiB近くあり、パースに時間がかかった
  • find_path の結果、問題の Thread はテレメトリやメトリクスツールのバックグラウンドスレッドではなく、リクエストを処理する Puma thread だった
  • ActiveSupport::SubscriberQueueRegistry はRails 6.1で、イベント名ごとの ActiveSupport::Subscriber 一覧を保存するスレッド別 Hash として動作する
  • そのregistryは Hash を参照しており、その中の Array の1つが ActiveSupport::Notifications::Event を保持していた
  • その Event はさらに @children 配列を通じて32,067個以上のchild Event オブジェクトを参照していた
  • 最初のchild Event の名前は redirect_to.action_controller で、内部には ActionDispatch::Request オブジェクトが含まれていた

異常なリクエストが再現の手がかりに

  • ヒープ内の ActionDispatch::Request には実際のルートと有効な公開リソースIDがあったが、クエリパラメータは細工された形だった
  • リクエストパスには password=[FILTERED] が含まれており、機密情報のクリーニング処理が介在したことを示していた
  • 同じパスとパラメータで本番アプリにシークレットブラウザからリクエストすると、500 server error が発生した
  • ログには URI::InvalidURIError が残り、リクエストが到達したDynoも確認できた
  • そのDynoは当時正常なメモリ使用量を示していたが、しばらくデプロイを止めて観察するとリーク傾向が現れた
  • ローカルでは activesupport Gemに binding.pry と puts デバッグを入れ、同じ状況とバックトレースを再現した

実際の原因はRailsとBugsnag変更の組み合わせだった

  • エラーのバックトレースはRuby標準ライブラリの uri Gemを指しており、これはBugsnagの Bugsnag.cleaner.clean_url で使われていた
  • このコードは ActiveSupport::Notifications.subscribe ブロック内でRails breadcrumb URLをクリーニングする処理にあった
  • 問題は2つが組み合わさった形だった
    • Rails 6.1の ActiveSupport::Subscriber は Event#children と共有 Array でイベントを追跡する
    • Bugsnagの変更はRails breadcrumb URLのクリーニングに URI を使い、不正なURIで例外が発生し得るものだった
  • URI がinvalid URIでエラーを上げると、Bugsnagのsubscribeブロックが ActiveSupport::Notifications::Event 処理中に例外を発生させる
  • その例外によりparent Event が Subscriber#event_stack からpopされず、parent Event が残ってメモリをリークした
  • parent Event は #children 配列でchild Event を参照し続け、より多くのメモリを保持する
  • John Hawthorn によるRails 7.1の修正は、Event#children の概念とイベント追跡用の共有 Array を削除し、2つのリーク原因をまとめてなくした

解決策はBugsnagアップグレードとRailsアップグレードだった

  • Rails最新版ではJohn Hawthornの修正により、この問題はもう発生しない
  • 当時のアプリはRails 6.1だったため、Railsの修正効果をすぐには受けられなかった
  • Bugsnagはすでに Bugsnag.cleaner.clean_url がinvalid URIで例外を上げないよう修正 していた
  • 短期的な解決策は、その修正を含む Bugsnag Gemバージョンへアップグレードすることだった
  • 長期的な解決策はRailsバージョンをアップグレードすることだった
  • 最初のメモリスパイクのタイミングと重なった変更はBugsnag v6.26.0 から v6.26.1 へのアップグレードであり、目的は別の依存関係のdeprecation warningを直すことだった

関連記事

1件のコメント

 
GN⁺ 2024-05-12
Hacker Newsの意見

  • 手動メモリ管理がなぜそこまで怖がられるのか理解できない。RAII と明確な所有権ルールさえあれば、メモリ管理は簡単なエンジニアリング作業だ
    むしろ参照カウントや共有ポインタを強制するフレームワークのほうが難しく感じる。所有権が曖昧になるからだ
    自分で作ったなら自分で解放し、渡したならもう気にしない。ハンドルやソケットのような OS リソースも自動リソースマネージャなしで手動管理しているのに、わざわざ自動メモリ管理で設計を複雑にする理由があるようには思えない

    • 手動メモリ管理は、ソフトウェアを推論するときの 認知負荷 を増やす。ワーキングメモリの容量は人によって大きく異なり、複雑なシステムを設計する際の性能を制限する要因になる
      長年開発してきて、ほとんどの開発者はメモリ管理まで同時に推論できるほどワーキングメモリに余裕がないと考えるようになった。やり方を機械的に知っていても、頭の中であまりに多くのことをジャグリングしていると見落としてしまう
      逆に、手動メモリ管理をほぼ無理なく毎回正しくこなせる少数の人もいる。彼らにとっては本当に簡単なことなので、なぜ他の人には難しいのか実感しにくい。そういう人には自動メモリ管理の利点は不明瞭で、欠点ばかりが大きく見えることがある
    • メモリバグ は、すでに解決済みに近いバグ分類だと思う。循環参照を処理できる現代的なガベージコレクタを持つ言語を使えば、プロジェクト全体を通してメモリバグに一度も遭遇しない可能性が高い
      大まかに言えば、こうしたバグが別のバグに置き換わったのではなく、単に消えたのだ。プログラマにより多くの仕事を要求することもなく、むしろ手動メモリ管理よりやることを減らしてくれる
      もちろんガベージコレクションが常に勝つわけではなく、実際の欠点もある。しかし大半のプログラムでは、現代的なガベージコレクタは十分によくできていて、その欠点は大きな問題にならない
    • メモリ管理そのものが難しいというより、開発者が完璧ではないので 未定義動作 やリークがまったくないプログラムを書くのが難しいのだ。たった一度のミスで、CVE、長時間稼働するプログラムの段階的なメモリ増加、1000回に1回だけ発生するバグが生じうる
      ロジックバグにも似た問題はあり、Java のような言語でもまれにメモリリークは起こりうるが、メモリ安全な言語は改善だ。TypeScript が JavaScript より優れているのと似ている。メモリエラーを 1% から 0.01% に減らせる自動化があるのに、なぜリークや未定義動作の防止を手動の関心事のままにしておく必要があるのかわからない
      Java のように簡単だがオーバーヘッドのあるガベージコレクション言語を使うこともできるし、Rust のように学習曲線はあるがオーバーヘッドのない所有権強制言語を使うこともできる。ロジックバグも厄介だが、メモリバグは明確なエラーメッセージを出さなかったり、発生してもプログラムが停止しなかったりすることがあり、とりわけ悪名高い
      余談だが、形式検証 もある種のバグを事実上排除する方法だ。今のところ正確性が最重要のシステムでしか見かけないが、メモリ管理と違って欠点が大きすぎるからだ。コードは極端に冗長で扱いづらく、特定の構造を強制する。しかし形式検証が改善されれば、これもより主流になると思う
    • 10年間 24/7 システムで 手動メモリ管理 をしてきたが、懐かしくはない。それ自体が難しいとか怖いというわけではないが、参照循環が起こりうる構造や、参照をあちこち移動させるイベントハンドラベースのアーキテクチャでは、問題領域そのものに集中する代わりに、メモリ管理設計を非常に慎重に行う必要がある
    • 大手テック企業の脆弱性の 35% が use-after-free バグによるという点が、答えの一部だ。深刻な脆弱性の 90% 以上は、メモリ安全言語では不可能なメモリバグから生じている

  • 「私は本物のプログラマではない。動くようにあれこれつぎはぎして先に進む。本物のプログラマなら『動いてはいるけど、あちこちでメモリが漏れてますね。直すべきでは？』と言うだろう。私はただ、リクエスト10回ごとに Apache を再起動するだけだ。」 — Rasmus Lerdorf, PHP Non-Designer
    https://en.wikiquote.org/wiki/Rasmus_Lerdorf

    • プロセス寿命を正確に把握しているなら、free() を決して呼ばないこと も有効なメモリ管理戦略だ

  • 昔働いていた会社は、メモリリークで 500 万ドルを失う最も間抜けな方法賞をもらえそうだった
    90年代の Solaris のプリンタドライバに メモリリーク があった[1]。当時、大手銀行の契約社員として働いていたが、その頃は契約確認におけるファクスの法的地位が法廷で十分に検証されておらず、銀行は取引をファクスで記録していた。ファクスを送るシステムは特定のプリンタにも文書を送り、取引確認書を印刷していた。そして誰かがその確認書を受け取り、相手方に電話で読み上げて通話録音[2]に残し、法的な確認にしていた
    ある日、メモリリークのせいでプリンタドライバが落ち、確認書が1通出力されなかったため、担当者は電話で読み上げることができなかった。市場が大きく動き、相手方はその取引を DK 扱いにした[3]。銀行の幹部がどれだけ騒いでも無駄で、500 万ドルの損失を帳簿に計上したうえで、その銀行とは二度と取引しないという方針を作った[4]。ファクス用プリンタのジョブは Windows NT に移された
    [1] 優れた本『Expert C Programming』によれば、この問題は当時 Sun Microsystems の CEO だった Scott McNealy が、CEO であるにもかかわらず性能の低いワークステーションを渡されて頻繁にこの問題に遭遇し、十分に不満を述べた結果、開発者たちが最終的に修正したという https://progforperf.github.io/Expert_C_Programming.pdf
    [2] 銀行の証券部門の通話は、法務およびコンプライアンス上の理由からほぼ常に録音される
    [3] DK は "Don't know" の略だ。相手がその取引を「知らない」と言えば、契約が成立したという事実そのものを争うことになる
    [4] 相手は別の場所で取引し、別の銀行に手数料を払えば済むので、おそらくこちらのほうが損だったはずだ

    • 冷笑的すぎるのかもしれないが、多くの企業が、自分たちに莫大な損失をもたらす取引を事後的に認めるだろうかとは思う。手続き上、書面確認と電話確認が必要で、その電話がなかったのなら、なぜ相手方ではなくこちらが損失をかぶるのか疑問だ
      Citi も融資を早く返しすぎたことを理由に訴訟を起こされていた。金融業界では、自分に有利なら誰もが書面契約を盾に強く出るものだと思う

  • Cでは Valgrind のおかげでリークを見つけるのはとても簡単
    修正するほうが難しいが、設計が正しければたいていは簡単。通常、呼び出し元のために確保する関数でない限り、同じ関数内で確保して解放する。呼び出し元のために確保する関数なら、その呼び出し自体を呼び出し元側の確保と見なす

    • 難しいのはバグを 再現 すること
      コードベースを静的解析したとき、エラー処理経路が問題の最も一般的な原因だった
    • Cでも似たように考えるが、これを 抽象化の中の異なるスコープレベル として捉える
      ブロックスコープ、関数スコープ、ファイルスコープ、グローバルスコープがあるように、問題領域や解法の抽象化であるモデルにも複数のレベルのスコープがある。ただし、これが教育されているのは見たことがない
      あるスコープが $SCOPE::foo()`` でリソースを取得し、$SCOPE::cleanup()` で解放していない場合は、目視でかなり見つけやすい。コーディングに飛び込む前に、問題領域と提案された解法をモデリングする能力は有用

  • Yahooについて聞いた話を思い出す。広告サーバーにメモリリークがあり、およそ10000リクエストの後に メモリ不足 になっていた
    解決策は8000リクエスト後にサーバーを再起動することだった。この方式は1〜2年は通用したが、その後は8000リクエスト後でもメモリ不足になり始めた
    次の解決策は6000リクエスト後にサーバーを再起動することだった

    • 平均的な広告サーバーでは 8000リクエスト はおよそ500ミリ秒ほど
      その方式が成り立つには、再起動がとてつもなく速くなければならない

  • Rails開発者だった頃は、こうした問題にハードウェアを追加投入するのが、生産性のための妥当なトレードオフとして通っていた。こういう種類の問題を気にするなら、もっと厳格なツールを使えばいいという空気だった
    個人的には完璧主義の傾向があるのでそのアプローチを受け入れにくいが、実際に機能する点は否定しがたい

    • サーバーを10分ごとに再起動してメモリリークを消していると認める代わりに、段階的アリーナ割り当て戦略 と呼べば受け入れられる

  • ガベージコレクションのある言語とない言語の両方を使ってきた。たいてい 手動管理 は書くのがより難しく、自動管理は問題解決がより難しい
    両方できる言語を使いたい。探索的なコードを書くときは自動メモリ管理が便利で、ある種のコードには手動メモリ管理が有利
    禁止と強制のあいだの中間地点を見つけられないのがもどかしい

    • Vはデフォルトでガベージコレクタを使うが、@[manualfree] 属性で関数やモジュールごとに簡単に無効化でき、v -gc none でプロジェクト全体でも無効にできる
      https://vlang.io
    • その言語は C++。ほとんど手動メモリ管理はしないが、やろうと思えばできる

  • 「リークをプロファイリングする各種ツール、ヒープダンプの読み解き方、よくあるリーク原因については多くの文章が書かれてきた」
    うっ、リークと ヒープダンプ とは。誰かもっと健康的な食生活が必要そうだ