はじめに: シンプルな検索なのにとっても遅い処理がある？
本番運用しているRailsアプリケーションで、とても表示に時間がかかる画面を見つけたので、ボトルネックを調査していました。
あれこれ調べた結果、以下のクエリがとても遅いことがわかりました（20秒近くかかる）。
# 特定の期間に発生した注文情報を取得する
Order.preload(:user).where(ordered_at: ordered_from_to)
SQL自体は速い
最初はテーブルに適切なindexが張られていないのかと思い、to_sqlで発行されるSQLを確認し、psql上で実行したり、実行計画を確認したりしましたが、一瞬でデータが返ってくるし、実行計画を見ても怪しい箇所はありません。
うーん、おかしい。
ちなみに上のコードを実行すると、データが多い画面だと1000件ぐらいのOrderレコードが返ってきます。
しかし、数十万件のレコードが返るような場合はともかく、1000件程度であれば、いくらなんでも20秒は時間がかかりすぎです。
pluckを使えば速い
「SQLはすぐに返ってくる、ということは、ActiveRecordを経由するときだけ何か問題がある？」と考え、pluckを使うようにコードを変えてみました。
Order.where(ordered_at: ordered_from_to).pluck(:id)
するとデータが一瞬で返ってきました。
うむ、やはりActiveRecordが何か悪さをしてそうです。
モデルに怪しいafter_findを発見！
そこでOrderモデルの実装を確認して怪しい箇所がないか調べたところ・・・あ、こいつか！？
class Order < ApplicationRecord
# ...
belongs_to :user
# ...
after_find :discount_for_premium
# 注：実務のコードをそのまま載せるわけにはいかないので、これは「イメージ」です。
# 「そもそものロジックがおかしい」みたいなツッコミはなしでお願いします。
def discount_for_premium
# ↓このuserが怪しい
if user.premium? && amount >= 1000
self.amount -= 100
end
end
after_findで呼び出されるdiscount_for_premiumで、userにアクセスしている箇所が怪しいです。
ためしにafter_findを無効化して、最初のコードを実行してみましょう。
# after_findを無効化してからOrderを読み込む
Order.skip_callback(:find, :after, :discount_for_premium)
Order.preload(:user).where(ordered_at: ordered_from_to)
こうすると一瞬でデータが返ってきました！
犯人はやはりafter_findのようです。
after_findがあると遅くなる原因
なぜafter_findがあると遅くなるのか？
それはpreload(:user)でuserが読み込まれる前にafter_findが発火し、N+1問題が発生するからです。
- DBの取得値を使ってOrderのインスタンスをnewする
-
after_findが発火する -
user.premium?の結果が必要だが、この時点ではまだuserが読み込まれていないので、usersテーブルをSELECTする
上のような処理が1000レコードに対して行われるため、usersテーブルに対するSELECTが1000回発生してN+1問題が起きるのでした！
なお、preloadの代わりにincludesやeager_loadを使っても同じです。
また、after_findの代わりにafter_initializeを使ってもダメでした。
参考：userの関連を使っている場合は話が別
なお、以下のようなコードであればN+1問題は起きません。
user.orders.where(ordered_at: ordered_from_to)
なぜなら、user.ordersのようにuserの関連を使ってordersを取得しているため、最初からuserがセットされた状態でOrderのインスタンスが生成されるからです。
回避策
今回は次のようにしてafter_findを使うのを避け、amountメソッドをオーバーライドするようにしました。
class Order < ApplicationRecord
# ...
belongs_to :user
# ...
- after_find :discount_for_premium
- def discount_for_premium
- if user.premium? && amount >= 1000
- self.amount -= 100
- end
- end
+ def amount
+ value = read_attribute(:amount)
+ return value if new_record?
+
+ user.premium? && value >= 1000 ? value - 100 : value
+ end
こうすればamountが呼び出されるまでuserにアクセスしないので、ちゃんとpreload(:user)している限り、N+1問題を避けることができます。
この対応で20秒近くかかっていた冒頭のロジックが0.2秒程度で完了するようになりました。
100倍速くなった！やった 
attributesを使うとDBの値がそのまま返るので注意
ただし、以下のようにattributesハッシュ経由でamountを取得しようとすると、上で実装した割引ロジックを通らないので注意が必要です。
# 割引ロジックを通った値が返る
order.amount #=> 2900
# attributesハッシュにするとDBの値がそのまま返る
order.attributes['amount'] #=> 3000
ボツ案：グローバルなフラグでafter_skipの実行可否を判断する
最初は以下のようにスレッドローカルなグローバル変数（フラグ）を用意し、そのフラグを使ってafter_findを無効化しようと考えていました。
module AfterFindSkipper
KEY = :skip_after_find
class << self
def enabled?
Thread.current[KEY]
end
def without_after_find
enable
yield
ensure
disable
end
private
def enable
Thread.current[KEY] = true
end
def disable
Thread.current[KEY] = false
end
end
end
class Order < ApplicationRecord
# ...
- after_find :discount_for_premium
+ # AfterFindSkipperのフラグが立っている場合はafter_findを実行しない
+ after_find :discount_for_premium, unless: -> { AfterFindSkipper.enabled? }
orders = nil
AfterFindSkipper.without_after_find do
# ここではafter_findコールバックが発火しない
# また、to_aで確実にDBからのロードを終わらせる
orders = Order.preload(:user).where(ordered_at: ordered_from_to).to_a
end
# userのロードが完了しているので、ここで各レコードに対してafter_findの処理を実行する
orders.each(&:discount_for_premium)
しかし、これだとafter_findによるN+1問題が起きそうな箇所を見つけて、その都度AfterFindSkipper.without_after_findを使うようにコードを書き直さないといけません。
コード量も増えますし、「忘れずにAfterFindSkipper.without_after_findを使う」という暗黙のルールが絶対に忘れられそうだったので、この方法はボツにしました。
まとめ
というわけで、この記事ではafter_findで関連先のレコードを参照するとN+1問題が起きますよ、という話と、その解決策を紹介しました。
after_findは滅多に使わないコールバックなので、今回のパフォーマンス問題は「まさかこれが原因だったとは」という感じでした。
このように予期せぬトラブルの原因になりかねないので、可能な限りafter_findに頼らないロジックを組んだ方がいいと思いました。まる。