Timeout.timeout を安全に使うのは難しい

こんにちは！Wantedly のエンジニアの縣です。

先日 Rails アプリケーションで ActiveRecord::StatementInvalid: PG::DuplicatePstatement というエラーが確率的に発生するという事象に遭遇し、その原因が Timeout.timeout と関係していてなかなか面白かったので記事に書き起こすことにしました。

（この記事を書くために今改めて調べてみたところ、 https://github.com/rails/rails/pull/41356 で ActiveRecord に関しては問題が解決していることがわかりました。が、記録として投稿しておきます。）

TL;DR

Ruby の Timeout.timeout は非同期例外を発生させる
非同期例外発生時に ActiveRecord の Connection の内部状態が壊れたことでエラーが大量発生した
Timeout.timeout を Rails アプリケーション (with puma) から安全に使うのは難しい...

問題発覚

ある日、ActiveRecord::StatementInvalid: PG::DuplicatePstatement: ERROR: prepared statement "a2" already exists というエラーがとあるサーバーから報告されました。

発生回数に偏りはあるものの、サーバー内で PostgreSQL とやりとりをする様々な場所で発生しており、その場では根本原因を特定することができませんでした。

エラーの内容自体は Prepared Statement の名前の重複で、どうやら ActiveRecord のなんらかの内部状態が壊れていそうだということがわかったため、試しにプロセスの再起動を行ったところ、問題は収束しました。

しかし、その場は収まったものの、その日以降不定期に同様の現象が発生するようになりました。このエラーの厄介だったところは、「たまにしか発生しないが、一度その状態に陥るとそのプロセスでは継続的にエラーが発生し続ける」というところでした。

根本原因の調査

まずはエラー発生時点付近でのアプリケーションコードの変更を探索しましたが、ここからは原因を見つけることもヒントを得ることもできませんでした。

しばらく諦めていたのですが、チームメイトの塩津くんが、似たような状況になっていることを報告している issue を発見してくれました。

「一度 DuplicatePstatement が発生するとずっとそのエラーが発生し続ける」という issue です。

どうやら rack-timeout の利用者によく発生している事象であること、対応策も提案されていますが Reject されていることがわかりました。

我々のアプリケーションでは rack-timeout を使用していませんでしたが、issue の内容からTimeout.timeout が悪そうとアタリをつけて調査したところ、アプリケーションコード内で Thread + Timeout.timeout を使っているコードがあり、その近辺で特にエラーが発生しやすいこともわかりました。

コードとしては、「複数のメソッドをそれぞれ個別のスレッドを起動して実行し、一定時間内に処理が終わった処理の中から最も優先度の高い結果を取り出す」、というものでした。内部の処理は様々でしたが、例えば別サーバーへの API コールを含んでいたり RDB への問い合わせがあったりと、実行時間にもばらつきがあったため Timeout.timeout を用いて実行を打ち切るような実装になっていました。

何が起きていたか

ActiveRecord::ConnectionAdapter::PostgreSQLAdapter::StatementPool は、Prepared Statement を作るたびに新しい key を発行しますが、そのために以下のような実装を持っていました。（冒頭でも述べたように、現在は修正されています。）

def next_key
  "a#{@counter + 1}"
end

def []=(sql, key)
  super.tap { @counter += 1 }
end

DuplicatePstatement は、この部分の @counter の値と実際のコネクション上に用意された Prepared Statement の数の同期が取れなくなってしまっているために発生していました。

ではなぜ（不定期で）この同期が取れなくなっていたのでしょうか。原因はTimeout.timeoutが投げる非同期例外でした。

Timeout.timeout は Timeout.timeout(5) { sleep 10 } のように使用します。渡したブロックを実行しますが、指定した時間が経過するとブロックの実行を中断し、Timeout::Errorを投げます。

ここで重要なのは「ブロックの実行を中断する方法」です。

実装をみてみると、Timeout.timeout は以下のような処理を行っていることがわかります。

現在の Thread を x とする
経過時間を監視するための Thread y を作成
x でブロックの実行を開始
指定時間経過したら Thread y から Thread x に向かってx.raise

Thread#raise は、実行中のスレッド内に外部から例外を割り込ませるメソッドです。外部から割り込みで例外を飛ばすので、対象スレッドは「どこで実行が中断されるかわからない」という状態になります。

ここで ActiveRecord の話に戻ると、「 @counter + 1 をベースに Prepared Statement を用意する」 → 「 @counter += 1 する」の間に timeout が発生したことで、PostgreSQL コネクションの状態と@counter の状態の一貫性が崩れ、 DuplicatePstatement の大量発生につながったと考えられます。

どう解決したか

長命なコネクションオブジェクトの内部状態が壊れるという問題なので、問題が起きたらオブジェクトを破棄・再生成することで解決できるのではないかと考え、reconnect! を例外発生時に呼ぶようにしてみました。

が、これだけでは解決には至りませんでした。我々のサーバーではスレッドベースでリクエストをさばく puma を利用しており、例外発生からリカバリまでの間に別リクエストの処理を始めてしまうことがあるためではないかと考えています。

最終的には https://github.com/rails/rails/pull/25827 こちらの PR を参考に以下のようなモンキーパッチを当てて解決しました。

require 'active_record/connection_adapters/postgresql_adapter'

module ActiveRecord
  module ConnectionAdapters
    class PostgreSQLAdapter
      class StatementPool
        def next_key
          "a#{SecureRandom.uuid.delete('-')}"
        end
      end
    end
  end
end

@counter という内部状態に依存することをやめ、毎回 UUID を生成することでユニークな key を組み立てるように変更しています。

これによって、内部状態が壊れることもなくなり、問題が完全に収束したことを確認しました。

Timeout.timeout は難しい

先ほどのモンキーパッチを書くにあたって参考にした PR は、2016 年にオープンされていました。そのほかにもたくさんの issue が報告されており、解決方法も何パターンか提案されていました。

しかし、そのほとんどが Rails チームによって decline されています。

これは、「Timeout.timeout が実行コンテキストの外部から例外を送り込んでくる」という事象が、根本的・網羅的な対処が難しい事象であるためです。実行コンテキストの外部から例外が飛んでくる事象に網羅的に対応するということは、「あらゆるコードで、いつ例外が飛んでくるかわからない」という前提に立ってコードを実装するということです。

それを考慮し始めるとほかにも問題が多すぎるので timeout はサポートしないというスタンスだったようです。https://github.com/rails/rails/pull/17607#issuecomment-70411672 （2015 年当時の結論であり、現在はスタンスが変化しているかもしれません。）

これは ActiveRecord や Rails に限った問題ではなく、アプリケーションコードであっても同様の難しさがあります。（リクエストスコープを超える寿命の「状態」を持つことは少ないので、相対的には問題になりにくいかもしれません。）

また Timeout.timeout のドキュメントをよく読むと、Ruby のスレッドが割り込めない処理（書き方によりますが、C 拡張などで C に制御が渡って Ruby に帰ってくるまでの間など）の間では timeout が考慮されないこともわかります。これは Thread#raise によって timeout が実装されているためです。

Timeout.timeout によって内部状態を壊されたくない場合に、Thread.handle_interrupt を用いて一時的に timeout によるエラーを無視するような実装を書くこともできますが、その場合もやはり timeout に指定した時間以上実行を続けてしまう可能性があり、本来やりたかったこと（= 指定した時間までで実行を切り上げる）を達成できません。

というわけで、 Timeout.timeout を正しく使うのはかなり難しく、特にサーバーアプリケーションのように状態が長生きするプロセスの中で安全に扱うのはほぼ不可能といえそうです。

指定した時間までで実行を切り上げるような処理が必要な場合は、以下のような方法で代替できないか検討してみると良さそうです。