Go to Qiita Advent Calendar 2024 Top
LoginSignup
15
7

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 5 years have passed since last update.

クラウドワークスAdvent Calendar 2018

Day 23
@YusukeIwaki

Railsで「ViewからカジュアルにSQLを叩いている」ところを列挙する

Last updated at Posted at 2018-12-23

まえおき

そこそこ大規模なRailsアプリを触っているといろんなモデルの状態を参照する魔のpartialを目にすることが稀によくあります。

Slice.png

_employees.html.erb というファイル名なので、Employeeを表示するだけ……かとおもいきや、評価だったりプロフィールだったり契約数だったり、たくさんのモデルを参照して頑張って表示してる！みたいなやつ。

一覧画面ではN+1問題がワンチャン起きてて、呼び元も呼び先もまぁまぁ規模があったりすると

EmployeesController#index
　employees/index.html.erb
　→ employees/_search_result.html.erb (600行くらい)
　　→ each { shared_partials/_employee.erb } (300行くらい)
　　　→その先で読んでいる EmployeeHelperのメソッドたち... (200行くらい)

結局なにをpreload/eager_loadすればN+1が回避できるの？？？ってのを調べるのにかなり苦慮します。
（というか、ここ１ヶ月くらいそれでかなり苦慮していました :sweat_smile: ）

その際に「ViewからカジュアルにSQLを叩いている場所を列挙する」っていうことをやると、割と効率的に調べることができたので、なんとなくその方法を書いておきます。

「おー、これは役に立つわ！」って人は多分ほとんど居ない気がするけど、Railsでこんなことできるんだ、くらいで思っていただければ幸いです。

シンプルな例で説明する

魔のパーシャルはサンプルコードを書くのもつらいので、おもちゃみたいなシンプルな例で説明します。

N+1を起こす例

モデル
class User < ApplicationRecord
  has_one :profile
end

class Profile < ApplicationRecord
  belongs_to :user

  def full_name
    "#{first_name} #{last_name}"
  end
end
app/controllers/users_controller.rb
class UsersController < ApplicationController
  def index
    @users = User.order(created_at: :desc)
  end
end
app/views/users/index.html.erb
<% if @users.present? %>
<ul>
<%= render partial: 'shared_partials/user', collection: @users %>
</ul>
<% end %>
app/views/shared_partials/_user.html.erb
<li><%= user.profile.display_name %></li>

image.png

イメージ、こんな感じで名前をずらーーっと出すだけ。

Railsコンソールを見てみると

Processing by UsersController#index as HTML
  User Load (0.4ms)  SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 20 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 12 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 13 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 14 LIMIT 1
  Profile Load (1.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 15 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 16 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 17 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 18 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 19 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 11 LIMIT 1
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 10 LIMIT 1
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 9 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 8 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 7 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 5 LIMIT 1
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 6 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 4 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 3 LIMIT 1
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 2 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 1 LIMIT 1
  Rendered shared_partials/_user.html.erb (23.2ms)
  Rendered users/index.html.erb within layouts/application (26.1ms)
Completed 200 OK in 29ms (Views: 22.5ms | ActiveRecord: 5.8ms)

(ﾉ∀`)ｱﾁｬｰ N+1が起きてます。

パーシャルViewから叩かれているSQLはどれ？？

先述のおもちゃな例だと

  • Userのロード User Load (0.4ms) SELECT users.* FROM users ORDER BYusers.created_at DESC × 1回
  • Profileのロード Profile Load (0.1ms) SELECT profiles.* FROM profilesWHEREprofiles.user_id = 7 LIMIT 1 × Userの数

のSQL呼び出しがされています。このうち、パーシャルViewから叩かれているのはどれでしょう？

・・・正解は、全部です。

ActiveRecordは遅延評価が基本なので、 @users = User.order(created_at: :desc) の時点ではSQLは叩かれず、ビュー側で必要となったときに初めてSQLが叩かれます。

ViewからカジュアルSQL叩いている場所を見つける

ようやく本題です。
ビューからSQLが叩かれている、ということを見つけ出すにはどうしましょう？という話です。

実は、単純にSQL叩いている場所を見つけるだけなら、ActiveRecord::Causeを入れることで、

  User Load (0.4ms)  SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC
  User Load (ActiveRecord::Cause) caused by /home/ubuntu/workspace/app/views/users/index.html.erb:1:in `_app_views_users_index_html_erb__2451733280735124226_22222060'
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 20 LIMIT 1
  Profile Load (ActiveRecord::Cause) caused by /home/ubuntu/workspace/app/views/shared_partials/_user.html.erb:1:in `_app_views_shared_partials__user_html_erb___725293523527224828_69998977673900'
　　　　　　：
　　　　　　：
  Profile Load (ActiveRecord::Cause) caused by /home/ubuntu/workspace/app/views/shared_partials/_user.html.erb:1:in `_app_views_shared_partials__user_html_erb___725293523527224828_69998977673900'
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 2 LIMIT 1
  Profile Load (ActiveRecord::Cause) caused by /home/ubuntu/workspace/app/views/shared_partials/_user.html.erb:1:in `_app_views_shared_partials__user_html_erb___725293523527224828_69998977673900'
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 1 LIMIT 1
  Profile Load (ActiveRecord::Cause) caused by /home/ubuntu/workspace/app/views/shared_partials/_user.html.erb:1:in `_app_views_shared_partials__user_html_erb___725293523527224828_69998977673900'

のようなログ出力からSQLを叩いている場所をある程度特定することはできます。

しかし今回は

  • コントローラからSQL叩いているところは別にいい。ビューから叩いているところだけ見たい
  • 全部の処理じゃなくて、特定のコントローラの特定のアクションに絞って、ビューからSQL叩くのを検出したい
    • #show アクションのようにN+1がそもそも起きない（起きづらい）ところでは無理してSQL叩くのを抑制しなくてもいい
    • 知らないコントローラのSQLログは出したくない

という要件です。

　

で、「上記の要件を満たすようなGemを新たに作ったぜ、ほい」だと記事として全然おもしろくないので、この記事では、車輪の再発明なところはあるかもしれないけど、それっぽいのを実現する仕組みを作った様子を順を追って書いていきます。

ActiveRecord::CauseがSQLを叩いている場所を特定している仕組みを探る

https://github.com/joker1007/activerecord-cause/blob/master/lib/activerecord/cause.rb を見ると ActiveRecord::LogSubscriber という文字が見えるので、「ActiveSupport::Notificationのサブスクリプションで実現しているんだなー」ってのがなんとなくわかります。

ためしに

config/initializers/hogefuga_subscription.rb
class HogeSubscriber < ActiveSupport::Subscriber
  def sql(event)
    Rails.logger.debug("sql: #{event.payload}")
  end
end

class FugaSubscriber < ActiveSupport::Subscriber
  def start_processing(event)
    Rails.logger.debug("start_processing: #{event.payload}")
  end

  def process_action(event)
    Rails.logger.debug("process_action: #{event.payload}")
  end
end

HogeSubscriber.attach_to :active_record
FugaSubscriber.attach_to :action_controller

のようにサブスクライバをinitializerで雑にアタッチさせてアプリケーションを実行すると・・・

Started GET "/users" for 115.69.238.232 at 2018-12-18 10:26:07 +0000
Cannot render console from 115.69.238.232! Allowed networks: 127.0.0.1, ::1, 127.0.0.0/127.255.255.255
sql: {:sql=>"SHOW TABLES LIKE 'schema_migrations'", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
  ActiveRecord::SchemaMigration Load (0.2ms)  SELECT `schema_migrations`.* FROM `schema_migrations`
sql: {:sql=>"SELECT `schema_migrations`.* FROM `schema_migrations`", :name=>"ActiveRecord::SchemaMigration Load", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
sql: {:sql=>"SHOW FULL FIELDS FROM `schema_migrations`", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
start_processing: {:controller=>"UsersController", :action=>"index", :params=>{"controller"=>"users", "action"=>"index"}, :format=>:html, :method=>"GET", :path=>"/users"}
Processing by UsersController#index as HTML
  User Load (0.3ms)  SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC
sql: {:sql=>"SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC", :name=>"User Load", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
sql: {:sql=>"SHOW FULL FIELDS FROM `users`", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
sql: {:sql=>"SHOW TABLES ", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
sql: {:sql=>"SHOW CREATE TABLE `users`", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
sql: {:sql=>"SHOW FULL FIELDS FROM `profiles`", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
  Profile Load (0.2ms)  SELECT `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` IN (20, 12, 13, 14, 15, 16, 17, 18, 19, 11, 10, 9, 8, 7, 5, 6, 4, 3, 2, 1)
sql: {:sql=>"SELECT `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` IN (20, 12, 13, 14, 15, 16, 17, 18, 19, 11, 10, 9, 8, 7, 5, 6, 4, 3, 2, 1)", :name=>"Profile Load", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
sql: {:sql=>"SHOW CREATE TABLE `profiles`", :name=>"SCHEMA", :connection_id=>21111960, :statement_name=>nil, :binds=>[]}
  Rendered shared_partials/_user.html.erb (23.2ms)
  Rendered users/index.html.erb within layouts/application (27.7ms)
process_action: {:controller=>"UsersController", :action=>"index", :params=>{"controller"=>"users", "action"=>"index"}, :format=>:html, :method=>"GET", :path=>"/users", :status=>200, :view_runtime=>34.6481842715888, :db_runtime=>3.6058969999999997}
Completed 200 OK in 51ms (Views: 34.6ms | ActiveRecord: 3.6ms)

いろいろログに出力されます。

ActiveRecord::Cause は sql.active_record を利用してSQLクエリ発行イベントを受けた際に Kernel#caller_locations というコールスタックを得るメソッドを使って、それっぽい（あらかじめconfigしておいたパスにマッチする）呼び出し箇所を抽出する＆ログ出力する、ということをやっています。

caller_locationsには具体的にどんな値が入っているか見てみる

ActiveRecord::Causeのコードでは caller_locationsに対して正規表現でマッチしたものを取得する、という処理があります。

  def get_locations
    return [] if ActiveRecord::Cause.match_paths.empty?
    caller_locations.select do |l|
      ActiveRecord::Cause.match_paths.any? do |re|
        re.match(l.absolute_path)
      end
    end
  end

でも、せっかくなので、そもそもこのcaller_locationsにはどういう値が入っているのか見ておこうと思います。

これも、とりあえず雑にイニシャライザでサブスクライバを仕掛けてみます。

config/initializers/hogefuga_subscription.rb
class HogeSubscriber < ActiveSupport::Subscriber
  def sql(event)
    return if ["SCHEMA", "EXPLAIN"].include?(event.payload[:name])

    caller_locations.each do |loc|
      Rails.logger.debug("caller_location:#{loc}")
    end
    Rails.logger.debug("sql: #{event.payload}")
  end
end

HogeSubscriber.attach_to :active_record

sql: {:sql=>"SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC", :name=>"User Load", :connection_id=>29621900, :statement_name=>nil, :binds=>[]}
  Profile Load (0.5ms)  SELECT `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` IN (20, 12, 13, 14, 15, 16, 17, 18, 19, 11, 10, 9, 8, 7, 5, 6, 4, 3, 2, 1)
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activesupport-4.2.10/lib/active_support/subscriber.rb:100:in `finish'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activesupport-4.2.10/lib/active_support/notifications/fanout.rb:102:in `finish'
　〜（中略）〜
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activerecord-4.2.10/lib/active_record/relation.rb:243:in `to_a'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activerecord-4.2.10/lib/active_record/relation.rb:622:in `blank?'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activesupport-4.2.10/lib/active_support/core_ext/object/blank.rb:24:in `present?'
caller_location:/home/ubuntu/workspace/app/views/users/index.html.erb:1:in `_app_views_users_index_html_erb___1313782717592081990_69842311333420'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/actionview-4.2.10/lib/action_view/template.rb:145:in `block in render'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activesupport-4.2.10/lib/active_support/notifications.rb:166:in `instrument'
　〜（中略）〜
caller_location:/usr/local/rvm/rubies/ruby-2.4.5/lib/ruby/2.4.0/webrick/httpserver.rb:140:in `service'
caller_location:/usr/local/rvm/rubies/ruby-2.4.5/lib/ruby/2.4.0/webrick/httpserver.rb:96:in `run'
caller_location:/usr/local/rvm/rubies/ruby-2.4.5/lib/ruby/2.4.0/webrick/server.rb:308:in `block in start_thread'
sql: {:sql=>"SELECT `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` IN (20, 12, 13, 14, 15, 16, 17, 18, 19, 11, 10, 9, 8, 7, 5, 6, 4, 3, 2, 1)", :name=>"Profile Load", :connection_id=>29621900, :statement_name=>nil, :binds=>[]}
  Rendered users/index.html.erb within layouts/application (38.3ms)
Completed 200 OK in 63ms (Views: 45.6ms | ActiveRecord: 3.9ms)

Railsのバージョンによって細かいところは違うと思いますが、

caller_location:/home/ubuntu/workspace/app/views/users/index.html.erb:1:in `_app_views_users_index_html_erb___1313782717592081990_69842311333420'

app/viewsから呼ばれているなー、ってのが改めてわかります。

じゃあ、仮にビューからSQLが叩かれないようなコードにした場合はどうなるでしょう。

app/view_models/shared_partial_user_view_model.rb
# app/views/shared_partials/_user.html.erbで使用する変数をまとめた、単なるValue Object
class SharedPartialUserViewModel
  def initialize(full_name:)
    @full_name = full_name
  end
 
  attr_reader :full_name
end

のように、パーシャルビューに必要なデータをまとめたビューモデルクラスをActiveRecord非依存な形で定義し

app/controllers/users_controller.rb
class UsersController < ApplicationController
  def index
    users = User.order(created_at: :desc).includes(:profile)
    @user_view_models = users.map{|u| SharedPartialsUserViewModel.new(full_name: u.profile.full_name }
  end

のように変えてからログを見てみます。

  Profile Load (0.6ms)  SELECT `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` IN (20, 12, 13, 14, 15, 16, 17, 18, 19, 11, 10, 9, 8, 7, 5, 6, 4, 3, 2, 1)
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activesupport-4.2.10/lib/active_support/subscriber.rb:100:in `finish'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activesupport-4.2.10/lib/active_support/notifications/fanout.rb:102:in `finish'
　〜（中略）〜
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/activerecord-4.2.10/lib/active_record/relation/delegation.rb:46:in `map'
caller_location:/home/ubuntu/workspace/app/controllers/users_controller.rb:6:in `index'
caller_location:/usr/local/rvm/gems/ruby-2.4.5/gems/actionpack-4.2.10/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
　〜（中略）〜
caller_location:/usr/local/rvm/rubies/ruby-2.4.5/lib/ruby/2.4.0/webrick/httpserver.rb:140:in `service'
caller_location:/usr/local/rvm/rubies/ruby-2.4.5/lib/ruby/2.4.0/webrick/httpserver.rb:96:in `run'
caller_location:/usr/local/rvm/rubies/ruby-2.4.5/lib/ruby/2.4.0/webrick/server.rb:308:in `block in start_thread'
sql: {:sql=>"SELECT `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` IN (20, 12, 13, 14, 15, 16, 17, 18, 19, 11, 10, 9, 8, 7, 5, 6, 4, 3, 2, 1)", :name=>"Profile Load", :connection_id=>29621900, :statement_name=>nil, :binds=>[]}
  Rendered users/index.html.erb within layouts/application (0.2ms)
Completed 200 OK in 34ms (Views: 6.5ms | ActiveRecord: 5.4ms)

お。期待通り

caller_location:/home/ubuntu/workspace/app/controllers/users_controller.rb:6:in `index'

になりました。app/viewsのファイルからの呼び出しが無くなってることがわかります。

以上のことから、ビューからSQLを叩いているかどうかは

  • sql.active_record のサブスクリプション
  • caller_locations の中に app/views/... がある？

を組み合わせることで判別できそうです。

特定のコントローラの特定のアクションでのみ、ビューからのSQL叩きを検出したい

ビューからSQLを叩いている箇所だけをログ出力するということはできました。
しかし、単純に attach_to で登録する方法だと、全部のコントローラの全アクションが対象になってしまいます。

app/controllers/users_controller.rb
class UsersController < ApplicationController
  def index
    @users = ...
  end

  def show
    @user = User.find(params[:id])
  end
end

のようなコントローラが有って「showアクションは対象外にしたい・・・」みたいなケースも大いにあるので、まずは特定のコントローラの特定のアクションだけをSQL監視対象にするようにしてみます。

またしても、雑にイニシャライザで・・・ :sweat_smile:

config/intializers/hogefuga_subscription.rb
class HogeSubscriber < ActiveSupport::Subscriber
  def sql(event)
    return if ["SCHEMA", "EXPLAIN"].include?(event.payload[:name])

    if caller_locations.any?{|loc| loc.absolute_path.include?("app/views") }
      Rails.logger.debug("SQL in view: #{event.payload}")
    end
  end
end

class ActionControllerSubscriber < ActiveSupport::Subscriber
  
  def start_processing(event)
    payload = event.payload
    if payload[:controller] == UsersController.to_s && payload[:action] == 'index'
      subscriptions[key_for(payload)] ||= ActiveSupport::Notifications.subscribe("sql.active_record", HogeSubscriber.new)
    end
  end

  def process_action(event)
    payload = event.payload
    if payload[:controller] == UsersController.to_s && payload[:action] == 'index'
      subscriptions.delete(key_for(payload)).try do |s|
        ActiveSupport::Notifications.unsubscribe(s)
      end
    end
  end

  private

  def key_for(payload)
    "#{payload[:controller]}##{payload[:action]}"
  end

  def subscriptions
    @__subscriptions ||= {}
  end
end

ActionControllerSubscriber.attach_to :action_controller

今回は、action_controllerのサブスクリプションをメインに使ってみました。
start_processing.action_controllerと process_action.action_controller が各リクエスト・レスポンスのトランザクションの開始と終了になることを利用し、start_processingでsubscribe, process_actionでunsubscribeするようにしました。

Started GET "/users/1" for 115.69.238.232 at 2018-12-23 13:51:17 +0000
Cannot render console from 115.69.238.232! Allowed networks: 127.0.0.1, ::1, 127.0.0.0/127.255.255.255
Processing by UsersController#show as HTML
  Parameters: {"id"=>"1"}
  User Load (0.3ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 1 LIMIT 1
  Rendered users/show.html.erb within layouts/application (75.3ms)
Completed 200 OK in 106ms (Views: 36.1ms | ActiveRecord: 54.3ms)


Started GET "/users" for 115.69.238.232 at 2018-12-23 13:51:21 +0000
Cannot render console from 115.69.238.232! Allowed networks: 127.0.0.1, ::1, 127.0.0.0/127.255.255.255
Processing by UsersController#index as HTML
  User Load (0.3ms)  SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC
SQL in view: {:sql=>"SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC", :name=>"User Load", :connection_id=>20179940, :statement_name=>nil, :binds=>[]}
  Profile Load (0.2ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 20 LIMIT 1
SQL in view: {:sql=>"SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 20 LIMIT 1", :name=>"Profile Load", :connection_id=>20179940, :statement_name=>nil, :binds=>[]}
  Profile Load (0.3ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 12 LIMIT 1
SQL in view: {:sql=>"SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 12 LIMIT 1", :name=>"Profile Load", :connection_id=>20179940, :statement_name=>nil, :binds=>[]}
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 13 LIMIT 1
SQL in view: {:sql=>"SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 13 LIMIT 1", :name=>"Profile Load", :connection_id=>20179940, :statement_name=>nil, :binds=>[]}
　　　　：
　　　　：
  Profile Load (0.1ms)  SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 1 LIMIT 1
SQL in view: {:sql=>"SELECT  `profiles`.* FROM `profiles` WHERE `profiles`.`user_id` = 1 LIMIT 1", :name=>"Profile Load", :connection_id=>20179940, :statement_name=>nil, :binds=>[]}
  Rendered shared_partials/_user.html.erb (23.6ms)
  Rendered users/index.html.erb within layouts/application (26.9ms)
Completed 200 OK in 30ms (Views: 24.8ms | ActiveRecord: 4.4ms)

期待通り、UsersControllerのindexのみを対象として、ViewからカジュアルにSQLを叩いているのをログ出力できました。

コントローラ側で「このアクションをSQL監視したい」と書けるようにする

「さすがにイニシャライザで各コントローラのことを書くのはちょっと・・・」と誰しもが感じるでしょう。
コントローラ側で

app/controllers/users_controller.rb
class UsersController < ApplicationController
  observe_sql_in_view only: [:index]

  def index
    @users = User.order(created_at: :desc).includes(:profile)
  end

  def show
    @user = User.find(params[:id])
  end
end

のように明示的に書けたら理想的ですね。ということでいざトライ

config/initializer/hogefuga_subscription.rb

# HogeSubscriberの定義は前と同じなので省略

class ActionControllerSubscriber < ActiveSupport::Subscriber
  class << self
    def target
      @@target ||= {}
    end

    def add_target(controller:, action:)
      target[key_for(controller, action)] = 1
    end

    def target?(controller:, action:)
      target[key_for(controller, action)] == 1
    end

    def key_for(controller, action)
      "#{controller}##{action}"
    end
  end

  def start_processing(event)
    payload = event.payload
    if ActionControllerSubscriber.target?(controller: payload[:controller], action: payload[:action])
      subscriptions[key_for(payload)] ||= ActiveSupport::Notifications.subscribe("sql.active_record", HogeSubscriber.new)
    end
  end

  def process_action(event)
    payload = event.payload
    subscriptions.delete(key_for(payload)).try do |s|
      ActiveSupport::Notifications.unsubscribe(s)
    end
  end

  private

  def key_for(payload)
    ActionControllerSubscriber.key_for(payload[:controller], payload[:action])
  end

  def subscriptions
    @__subscriptions ||= {}
  end
end

class ActionController::Base
  def self.observe_sql_in_view(only:)
    only.each do |action|
      ActionControllerSubscriber.add_target(controller: self.to_s, action: action)
    end
  end
end

ActionControllerSubscriber.attach_to :action_controller

対象とするコントローラ・アクションはクラス変数で保持し、ベタで文字列比較していたところを置き換えました。

ログは変わらずです。

SQL in view のログ出力を少しだけまともにする

SQL in view: {:sql=>"SELECT `users`.* FROM `users`  ORDER BY `users`.`created_at` DESC", :name=>"User Load", :connection_id=>16084600, :statement_name=>nil, :binds=>[]}

はちょっと雑すぎるので、少しだけまともにしましょう。HogeSubscriberを

  • color を使って目立たせる
  • SQL以外の情報やJSON構造はログ出力しない
  • クラス名をまともにする :sweat_smile:

のように、少し改変する。

class SqlInViewSubscriber < ActiveSupport::LogSubscriber
  IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]

  def sql(event)
    payload = event.payload
    log_sql_in_view(payload) unless IGNORE_PAYLOAD_NAMES.include?(payload[:name])
  end

  private

  def log_sql_in_view(payload)
    location = caller_locations.find{|loc| loc.absolute_path.include?("app/views/")}
    if location.present?
      logger.info("#{color("SQL in view", RED)}: #{payload[:sql]} caused by #{location}")
    end
  end
end

実際のログ出力はこんな感じになります :point_down:

image.png

それっぽい感じになったぞー＼(^o^)／わーい

まとめ

config/initializers/sql_in_view_subscription.rb
class SqlInViewSubscriber < ActiveSupport::LogSubscriber
  IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]

  def sql(event)
    payload = event.payload
    log_sql_in_view(payload) unless IGNORE_PAYLOAD_NAMES.include?(payload[:name])
  end

  private

  def log_sql_in_view(payload)
    location = caller_locations.find{|loc| loc.absolute_path.include?("app/views/")}
    if location.present?
      logger.info("#{color("SQL in view", RED)}: #{payload[:sql]} caused by #{location}")
    end
  end
end

class SqlInViewControllerSubscriber < ActiveSupport::Subscriber
  class << self
    def target
      @@target ||= {}
    end

    def add_target(controller:, action:)
      target[key_for(controller, action)] = 1
    end

    def target?(controller:, action:)
      target[key_for(controller, action)] == 1
    end

    def key_for(controller, action)
      "#{controller}##{action}"
    end
  end

  def start_processing(event)
    payload = event.payload
    if SqlInViewControllerSubscriber.target?(controller: payload[:controller], action: payload[:action])
      subscriptions[key_for(payload)] ||= ActiveSupport::Notifications.subscribe("sql.active_record", SqlInViewSubscriber.new)
    end
  end

  def process_action(event)
    payload = event.payload
    subscriptions.delete(key_for(payload)).try do |s|
      ActiveSupport::Notifications.unsubscribe(s)
    end
  end

  private

  def key_for(payload)
    SqlInViewControllerSubscriber.key_for(payload[:controller], payload[:action])
  end

  def subscriptions
    @__subscriptions ||= {}
  end
end

class ActionController::Base
  def self.observe_sql_in_view(only:)
    only.each do |action|
      SqlInViewControllerSubscriber.add_target(controller: self.to_s, action: action)
    end
  end
end

SqlInViewControllerSubscriber.attach_to :action_controller

Railsのロード時に :point_up_2: のようにパッチを当てて

app/controllers/users_controller.rb
class UsersController < ApplicationController
  observe_sql_in_view only: [:index]

  def index
    ...
  end
end

のように observe_sql_in_view で、「ViewからカジュアルにSQLを叩いている」ってのを検出したいアクションを指定すると

image.png

こんな感じでログに出て、べんり。

15
7
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
15
7

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?