Все мы постоянно пользуемся 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"
Top comments (0)