Все мы постоянно пользуемся rails-консолью. Она незаменима при отладке в development. Но и в боевом окружении временами тоже что-то требуется посмотреть. Недавно наткнулся на один неочевидный нюанс, который заставил поразбираться.

Есть некий код, который используетActiveRecord::Associations::Preloader для кастомной подгрузки ассоциации (выборочныйselect). Отлаживаю его в консоли:

products_scope=Product.select(:id,:name)ActiveRecord::Associations::Preloader.new(records:line_items,associations: :product,scope:products_scope).call

На проде можно предварительно для удобства перенаправить в консоль SQL-запросы:

ActiveRecord::Base.logger=Logger.new(STDOUT)

Что мы видим, когда запускаем этот код?

DEBUG -- :   Product Load (3.8ms)  SELECT "products"."id", "products"."name" FROM "products" WHERE "products"."id" = $1  [["id", 1092717]]DEBUG -- :   Product Load (1326.4ms)  SELECT "products"."id", "products"."name" FROM "products"

Товары подгружаются дважды. Первый раз, как и ожидается с фильтрацией по id товара. А вот второго быть вообще не должно, к тому же запускается full scan таблицы. И это production-окружении!. Получается AR-preloader не работает? почему так происходит?

Покопался в исходниках и понял, что прелоадер все-таки ни при чем. Проблема возникает при отображении результата выполнения команды в консоли. При этом под капотом дергается некий метод, который форматирует вывод. Какой именно, не понятно. Теоретически, это может быть метод этого самого результата, либо другого объекта с аргументом в виде результата. Попробуем выяснить, как именно.

Вызываемые методы могут быть залогированы при помощи модуляTracePoint. Он позволяет отлавливать разные типы событий, в том числе событияcall, вызываемые на объекте типаMethod. То есть, таким образом мы можем залогировать вызовы любых методов.

result=ActiveRecord::Associations::Preloader.new(records:line_items,associations: :product,scope:products_scope).call;1calls=[]trace=TracePoint.new(:call,:c_call)do|tp|iftp.binding.eval('self')==result||tp.parameters.any?{tp.binding.eval(_1.last)==resultrescuefalse}calls<<"#{tp.defined_class}##{tp.method_id} got called (#{tp.path}:#{tp.lineno})"endendtrace.enableresult

Результат, вывод которого хотим залогировать, присваиваем переменной, и гасим вывод команды присваивания. Далее отлавливаем вызовы методов, в которых либо аргументом являетсяresult либо принадлежащие самомуresult. Включаем логирование, инициируем вывод результата в консоль.

Далее нужно отключить логирование и посмотреть, что накопилось вcalls:

trace.disablecalls=>["Array#pretty_print got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:366)"]

Уже теплее,result содержит массив и для вывода в консоль используется один из методов модуляPP. Очевидно, что для отображения на каждом элементе массива вызывается еще какой-то метод. Изменим немного код:

result=ActiveRecord::Associations::Preloader.new(records:line_items,associations: :product,scope:products_scope).call[0];1trace.enableresult...trace.disablecalls=>["PP::ObjectMixin#pretty_print got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:317)","Module#instance_method got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:318)","UnboundMethod#bind_call got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:320)","Kernel#method got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:320)","Method#owner got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:323)","BasicObject#!= got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:323)","Module#== got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:323)","BasicObject#! got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:325)","PP::ObjectMixin#pretty_print_instance_variables got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:345)","Kernel#instance_variables got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:346)","Array#sort got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:346)","Symbol#<=> got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:346)"]

Немного покопавшись в исходникахPP, не сложно найти, что для вывода объекта все его instance-переменные выбираются и отображаются при помощиpp:

pp(obj.instance_eval(v))

ОбъектActiveRecord::Associations::Preloader содержит instance-переменную@preload_scope, в которой сохраненproducts_scope. При отображении с помощьюpp происходит выполенение запроса к базе, что и приводит к этой неочевидной ситуации.

ppProduct.select(:id,:name)D,[2023-09-04T15:55:01.574901#28800] DEBUG -- :   Product Load (1185.7ms)  SELECT "products"."id", "products"."name" FROM "products"