😱

N+1 問題を解決すりゃいいってもんでもないらしい

arawi

2024/09/30に公開

こんにちは！

ラブグラフ開発インターンの arawi です。

今日は Rails (ActiveRecord) を使っていると発生してしまいがちな N+1 問題についての記事です！

 TL;DRpreload は SQL でデータを取得したあとインスタンス化するので、大量のレコードを prelaod するととても重くなる

 想定する読者N+1 問題を理解している
Rails/ActiveRecord の経験がある
特に、preload を使ったことがある


 発端サービス上のとあるページの高速化を図るため、ページの SQL クエリを見直していました。

このページではカメラマン(Photographer)とカメラマンが1回の撮影で取った写真集(Album)、そして撮影された写真(Photograph)を表示していたのですが、アルバムや写真が preload や eager_load で事前読み込みされておらず、N+1 問題を引き起こしていました。

そこで、カメラマンに対し preload で写真を読み込むようにし、N+1 問題の解決を図りました。
# Controller#show
@photographer = photographer.preload(albums: :photographs)
当該ページには他にも N+1 問題が含まれており、それらも同時に解決しました。

 事件無事に多くの N+1 問題を解決し、ローカルでは望んだ高速化を実現することができました。

ステージングでも問題なく、満を持してリリースしたところ・・・
なんとページの読込時間が3秒が12秒になってしまいました！
急いで revert してもらい、調査にあたりました。

そのページはモデルの show のページでしたが、そのモデルに紐づく子モデルのレコードが多いほど遅くなっているようでした。

 修正本番でしか再現しなかったので、いろいろな手立てを試しました。

すると、発端のところで追加した preload を消すととたんに速くなることに気づきました。
# Controller#show
@photographer = photographer.preload(albums: :photographs)
この preload を消すと N+1 問題が発生するのにもかかわらず、消したほうが速くなったのです・・・

 考えたこの preload では、子モデルだけでなく孫モデルまで読み込んでいます。1人のカメラマンに対して、アルバムのレコード数は最大 1,000 、写真はそのそれぞれに対して 100 レコードほど紐づくので、合計 100,000 レコードの preload が発生します。これは確かに重そう。

でも、 SQL で 100,000 行読み込むくらいならそこまで重くないですよね？

 preload を知るさらなる原因を突き止めるため、 preload の実装を調べることにしました。

このときには次の記事がとても参考になりました。
https://zenn.dev/nasa/articles/250515c56b5797
記事によれば、preload では関連する子モデルを取得するため、最終的には子モデルのテーブルに対して where を呼んでいます。そして、その後 to_a を呼び、取得したレコードをインスタンス化します。
・・・インスタンス化？
なんか重そうな処理だな！！

 preload をプロファイルしてみるここで 推測するな、計測せよ の格言通り、プロファイルを行ってみることにしました。

ruby-prof を使い、1万レコードの親モデルと、それに紐づく子モデル61万レコードを preload してみます[1]。
require 'ruby-prof'

# プロファイリング開始
RubyProf.start

puts "Running the script..."
Parent.preload(:children).limit(10000).to_a

# プロファイリング終了
result = RubyProf.stop

# 結果の出力
File.open("profile_result.html", "w") do |file|
  printer = RubyProf::CallStackPrinter.new(result)
  printer.print(file)
end
RubyProf::CallStackPrinter を呼ぶことで、ツリーの形でメソッド呼び出しが出力されます。結果は以下の通り。
一部抜粋して、preload に関わるところを表示しています。

全体では処理に90秒かかりました。
重要なところを2つ取り出します。カッコ内のパーセンテージはその部分の処理にかかった合計時間の全体に占める割合です。

ActiveRecord::ConnectionAdapters::MySQL::DatabaseStatements#select_all (2.65%)

ActiveRecord::Persistence::ClassMethods#instantiate_instance_of (67.51%)
1つめの select_all は実際に SQL を叩く部分です。予想通り、ここには全然時間はかかっておらず、全体の 2.65% しか占めていないですね。

一方2つめの instantiate_instance_of は全体の 67.51% を占めています。やはりインスタンス化が重かったのか！
さらに instantiate_instance_of の内訳を見ると、以下の通り。

ActiveRecord::Associations::Association#set_inverse_instance(41.52%)

ActiveRecord::Base#_run_initialize_callbacks(7.16%)

ActiveRecord::AttributeMethods#[](4.85%)

ActiveRecord::Associations#init_internal(2.58%)

ActiveRecord::Base#_run_find_callbacks(2.31%)

ActiveRecord::Associations::Preloader::Association#association_key_name(1.04%)
データベースから取得した attributes からインスタンスを作って、preload の親子関係を紐づける部分は set_inverse_instance に含まれるようです。やっぱりここが一番重い。

しかし、_run_initialize_callbacks なんかも意外と重いですねー

 その後その後、インスタンス化に時間が食うとわかったので、preload は残しつつ、limit をつけることで子モデル、孫モデルの取得対象を必要最小限に絞りました。
# Controller#show
@photographer = photographer
@albums = @photographer.albums.preload(:photographs).limit(10)
# View 側も @albums を使って書き換える
その結果、表示時間を12秒 → 1秒まで減らすことができました！

 おわりにN+1 問題を解決すれば全部速くなると思っていました。ちゃんと計測して、ボトルネックを確かめることが大事（推測するな、計測せよ）という学びを得ました。

みなさんも preload を使うときは対象のレコード数に気をつけましょう〜！

脚注
目的が preload のテストなので、前述のモデルとは異なるモデルで計測しています ↩︎

ラブグラフのエンジニアブログPublication

corporate.lovegraph.me 出張写真撮影サービス『ラブグラフ』やオンライン写真教室『ラブグラフアカデミー』を提供しています

N+1 問題を解決すりゃいいってもんでもないらしい

TL;DR

想定する読者

発端

事件

修正

考えた

`preload` を知る

`preload` をプロファイルしてみる

その後

おわりに

Discussion