Нюансы использования rails-консоли

Все мы постоянно пользуемся 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; 1
calls = []
trace = TracePoint.new(:call, :c_call) do |tp|
  if tp.binding.eval('self') == result || tp.parameters.any? { tp.binding.eval(_1.last) == result rescue false }
    calls << "#{tp.defined_class}##{tp.method_id} got called (#{tp.path}:#{tp.lineno})"
  end
end
trace.enable
result

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

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

trace.disable
calls
=> ["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]; 1
trace.enable
result
...
trace.disable
calls
=> ["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 происходит выполенение запроса к базе, что и приводит к этой неочевидной ситуации.

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