bullet如何检测N+1问题
先在controller里构造出一个N+1查询，然后根据rails log打印出的提示“Add to your finder…”，查找bullet代码，在其中加入打印caller语句，看是哪里开始调用的
module Bullet
module Notification
class NPlusOneQuery < Base
def body
pp '----------------------'
pp caller
"#{klazz_associations_str}\n Add to your finder: #{associations_str}"
end得调用栈如下
["/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/notification/base.rb:41:in `body_with_caller'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/notification/base.rb:61:in `notification_data'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/notification/n_plus_one_query.rb:23:in `notification_data'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/notification/base.rb:45:in `notify_inline'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet.rb:177:in `block in gather_inline_notifications'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet.rb:243:in `block (2 levels) in for_each_active_notifier_with_notification'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/2.3.0/set.rb:306:in `each_key'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/2.3.0/set.rb:306:in `each'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet.rb:241:in `block in for_each_active_notifier_with_notification'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet.rb:240:in `each'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet.rb:240:in `for_each_active_notifier_with_notification'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet.rb:176:in `gather_inline_notifications'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/rack.rb:23:in `call'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/rack-1.5.5/lib/rack/etag.rb:23:in `call'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/rack-1.5.5/lib/rack/conditionalget.rb:25:in `call'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/rack-1.5.5/lib/rack/head.rb:11:in `call’",
# …可见其是通过增加一层rack来产生作用的，于是想将其call方法的调用栈打印出来，但鉴于里面@app.call(env)还调了下层rack，可能dump出来的东西太大，所以只关注下Bullet.perform_out_of_channel_notifications这段
module Bullet
class Rack
include Dependency
def call(env)
# …
status, headers, response = @app.call(env)
# ...
binding.trace_tree(htmp: 'bullet_perform') do
Bullet.perform_out_of_channel_notifications(env)
end
end
[status, headers, response_body ? [response_body] : response]
ensure
Bullet.end_request
end得调用栈如下
但这其实看不出什么，只能看到发现它是将每种警告（notification）塞给警报器（notifier），然后调用notification.notify_out_of_channel来输出警告信息
def for_each_active_notifier_with_notification
UniformNotifier.active_notifiers.each do |notifier|
notification_collector.collection.each do |notification|
notification.notifier = notifier
yield notification
end
end
end于是，回到Bullet::Notification::NPlusOneQuery，看其是如何生成的
module Bullet
module Notification
class NPlusOneQuery < Base
def initialize(callers, base_class, associations, path = nil)
pp '--------------'
pp caller
super(base_class, associations, path)
@callers = callers
end打印出的调用栈很多，连query cache也会new NPlusOneQuery，摘取一条如下
Load (1.9ms) SELECT FROM "stores" WHERE "stores"."id" = $1 ORDER BY "stores"."created_at" ASC LIMIT 1 [["id", "......................"]]
"--------------"
["/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/detector/n_plus_one_query.rb:91:in `new'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/detector/n_plus_one_query.rb:91:in `create_notification'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/detector/n_plus_one_query.rb:25:in `call_association'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/bullet-6.0.0/lib/bullet/active_record41.rb:164:in `reader'",
"/Users/yuanzhipeng/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/activerecord-4.1.16/lib/active_record/associations/builder/association.rb:110:in `store'",
"/Users/yuanzhipeng/Projects/rebasing/r................../app/models/...................rb:31:in `store_name'",
"/Users/yuanzhipeng/Projects/rebasing/............../app/views/.................../index.html.erb:69:in `block (2 levels) in _app_views_………..._index_html_erb___202976205520604906_70249725434600’”,可见各种Notification是通过重写ActiveRecord的方法，在其中进行拦截而产生的
# bullet-6.0.0/lib/bullet/active_record41.rb
module Bullet
module ActiveRecord
def self.enable
require 'active_record'
::ActiveRecord::Associations::SingularAssociation.class_eval do
# call has_one and belongs_to associations
alias_method :origin_reader, :reader
def reader(force_reload = false)
result = origin_reader(force_reload)
if Bullet.start?
if @owner.class.name !~ /^HABTM_/ && !@inversed
Bullet::Detector::NPlusOneQuery.call_association(@owner, @reflection.name)
Bullet::Detector::NPlusOneQuery.add_possible_objects(result)
end
end
result
end
endcall_association产生的Notification会塞入Thread.current[:bullet_notification_collector]，然后add_possible_objects会将对象的类和id记录到Thread.current[:bullet_possible_objects]中
但这还是没看出bullet_notification_collector和bullet_possible_objects怎样（甚至有没有）被用于统计N+1。观察rack的代码，感觉其实可以直接跟踪Bullet.start_request和Bullet.end_request包裹查询语句时的执行过程，这样dump出的调用栈会比rack中的少很多，分析起来也方便一些，于是：
[3] pry(main)> binding.trace_tree(htmp: 'bullet_not_in_rack') do [3] pry(main)* begin [3] pry(main)* Bullet.start_request [3] pry(main)* PgOrder.limit(2).map(&:store) [3] pry(main)* Bullet.perform_out_of_channel_notifications [3] pry(main)* ensure [3] pry(main)* Bullet.end_request [3] pry(main)* end [3] pry(main)* end PgOrder Load (36.6ms) SELECT "orders".* FROM "orders" ORDER BY orders.created_at DESC LIMIT 2 Store Load (23.4ms) SELECT "stores".* FROM "stores" WHERE "stores"."id" = $1 ORDER BY "stores"."created_at" ASC LIMIT 1 [["id", “………………."]] Store Load (37.8ms) SELECT "stores".* FROM "stores" WHERE "stores"."id" = $1 ORDER BY "stores"."created_at" ASC LIMIT 1 [["id", "………………."]] user: yuanzhipeng USE eager loading detected PgOrder => [:store] Add to your finder: :includes => [:store] Call stack /Users/yuanzhipeng/Projects/rebasing/………../bin/rails:8:in `' => [UniformNotifier::RailsLogger] [4] pry(main)>
得调用栈如下
再跟踪一下1+1（不是N+1）的情况，即limit(1).map，得调用栈
一对比，可以发现1+1时Bullet.notification_collector.collection是空
于是检查下call_association的执行路径上，是什么条件导致Bullet.notification_collector没有调用add
module Bullet
module Detector
class NPlusOneQuery < Association
extend Dependency
extend StackTraceFilter
class <<self #="" executed="" when="" object.assocations="" is="" called.="" #="" first,="" it="" keeps="" this="" method="" call="" for="" object.association.="" #="" then,="" it="" checks="" if="" this="" associations="" call="" is="" unpreload.="" # if="" it="" is,="" keeps="" this="" unpreload="" associations="" and="" caller.="" def="" call_association(object,="" associations)="" return="" unless="" bullet.start?="" return="" unless="" bullet.n_plus_one_query_enable?="" return="" unless="" object.bullet_primary_key_value="" return="" if="" inversed_objects.include?(object.bullet_key,="" associations)="" add_call_object_associations(object,="" associations)="" bullet.debug('detector::nplusonequery#call_association',="" "object:="" #{object.bullet_key},="" associations:="" #{associations}")="" if="" !excluded_stacktrace_path?="" &&="" conditions_met?(object,="" associations)="" bullet.debug('detect="" n="" +="" 1="" query',="" "object:="" #{object.bullet_key},="" associations:="" #{associations}")="" create_notification="" caller_in_project,="" object.class.to_s,="" associations="" end="" end="" private="" def="" create_notification(callers,="" klazz,="" associations)="" notify_associations="Array(associations)" -="" bullet.get_whitelist_associations(:n_plus_one_query,="" klazz)="" if="" notify_associations.present?="" notice="Bullet::Notification::NPlusOneQuery.new(callers," klazz,="" notify_associations)="" bullet.notification_collector.add(notice)="" end="" end<="" code=""></self>检查call_association中!excluded_stacktrace_path?和conditions_met?(object, associations)的返回值，发现1+1时conditions_met?为false，而N+1时，两次conditions_met?都为true，因此1+1不会有create_notification
而conditions_met?是这样的：
def conditions_met?(object, associations)
possible?(object) && !impossible?(object) && !association?(object, associations)
end
def possible?(object)
possible_objects.include? object.bullet_key
end
def impossible?(object)
impossible_objects.include? object.bullet_key
end
# check if object => associations already exists in object_associations.
def association?(object, associations)
value = object_associations[object.bullet_key]
value&.each do |v|
# associations == v comparison order is important here because
# v variable might be a squeel node where :== method is redefined,
# so it does not compare values at all and return unexpected results
result = v.is_a?(Hash) ? v.key?(associations) : associations == v
return true if result
end
false
end在调用栈上搜索possible_objects从何处填入，发现是被patch过的find_by_sql
当某类的查询返回条数大于1时，就将其纳入“可能N+1”中
module Bullet
module ActiveRecord
def self.enable
require 'active_record'
::ActiveRecord::Base.class_eval do
class << self
alias_method :origin_find_by_sql, :find_by_sql
def find_by_sql(sql, binds = [])
result = origin_find_by_sql(sql, binds)
if Bullet.start?
if result.is_a? Array
if result.size > 1
Bullet::Detector::NPlusOneQuery.add_possible_objects(result)
Bullet::Detector::CounterCache.add_possible_objects(result)
elsif result.size == 1
Bullet::Detector::NPlusOneQuery.add_impossible_object(result.first)
Bullet::Detector::CounterCache.add_impossible_object(result.first)
end
elsif result.is_a? ::ActiveRecord::Base
Bullet::Detector::NPlusOneQuery.add_impossible_object(result)
Bullet::Detector::CounterCache.add_impossible_object(result)
end
end
result
end
end
end而impossible_objects，则在整个调用栈里都没找到add_impossible_object，应该就是因为走了result.size > 1的add_possible_objects而不走add_impossible_object。那为什么还需要possible?(object) && !impossible?(object)呢？未明……
至于association?，其object_associations[object.bullet_key]所得的set是空的，所以没有each循环
搜索一下代码，见有add_object_associations及一些调用的地方，其中一个如下：
::ActiveRecord::FinderMethods.class_eval do
# add includes in scope
alias_method :origin_find_with_associations, :find_with_associations
def find_with_associations
return origin_find_with_associations { |r| yield r } if block_given?
records = origin_find_with_associations
if Bullet.start?
associations = (eager_load_values + includes_values).uniq
records.each do |record|
Bullet::Detector::Association.add_object_associations(record, associations)
end
Bullet::Detector::UnusedEagerLoading.add_eager_loadings(records, associations)
end
records
end
end但add_object_associations在刚才的调用栈是没有找到的。根据注释，这应该是重写了includes的执行路径，在其中进行拦截。于是跟踪一下includes：
[27] pry(main)> binding.trace_tree(htmp: 'bullet_not_in_rack') do
[27] pry(main)* begin
[27] pry(main)* Bullet.start_request
[27] pry(main)* PgOrder.limit(2).includes(:store).map(&:store)
[27] pry(main)* Bullet.perform_out_of_channel_notifications
[27] pry(main)* ensure
[27] pry(main)* Bullet.end_request
[27] pry(main)* end
[27] pry(main)* end
PgOrder Load (23.2ms) SELECT "orders".* FROM "orders" ORDER BY orders.created_at DESC LIMIT 2
Store Load (30.7ms) SELECT "stores".* FROM "stores" WHERE "stores"."id" IN ('02573e9c-6bee-4771-a1e3-90cdc945d68b') ORDER BY "stores"."created_at" ASC
=> [UniformNotifier::RailsLogger]
[28] pry(main)>得调用栈：
这includes对add_object_associations的调用是在重写的preloaders_on里的，那find_with_associations应该是其他情况了
由于这次塞入了object_associations，所以possible?(object) && !impossible?(object) && !association?(object, associations)为false，便没有再create_notification了
那“多余preload的检测”是怎样执行的呢？猜测是因为没有了call_association的add_call_object_associations，所以应该能在Bullet.perform_out_of_channel_notifications时，筛选出有object_associations但无call_object_associations的associations，进而得出多余的preload