DEV Community

Sergei Malykh
Sergei Malykh

Posted on

Нюансы использования 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
Enter fullscreen mode Exit fullscreen mode

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

ActiveRecord::Base.logger = Logger.new(STDOUT)
Enter fullscreen mode Exit fullscreen mode

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

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"
Enter fullscreen mode Exit fullscreen mode

Товары подгружаются дважды. Первый раз, как и ожидается с фильтрацией по 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
Enter fullscreen mode Exit fullscreen mode

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

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

trace.disable
calls
=> ["Array#pretty_print got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:366)"]
Enter fullscreen mode Exit fullscreen mode

Уже теплее, 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)"]
Enter fullscreen mode Exit fullscreen mode

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

pp(obj.instance_eval(v))
Enter fullscreen mode Exit fullscreen mode

Объект 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"
Enter fullscreen mode Exit fullscreen mode

Image of Datadog

Create and maintain end-to-end frontend tests

Learn best practices on creating frontend tests, testing on-premise apps, integrating tests into your CI/CD pipeline, and using Datadog’s testing tunnel.

Download The Guide

Top comments (0)

Sentry image

See why 4M developers consider Sentry, “not bad.”

Fixing code doesn’t have to be the worst part of your day. Learn how Sentry can help.

Learn more

👋 Kindness is contagious

Please leave a ❤️ or a friendly comment on this post if you found it helpful!

Okay