Нюансы использования rails-консоли
Tags: ruby
Published: 2023-09-04 13:12:00

---
title: Нюансы использования rails-консоли
published: true
description: 
tags: ruby
# cover_image: https://direct_url_to_image.jpg
# Use a ratio of 100:42 for best results.
# published_at: 2023-09-04 13:07 +0000
---

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

Есть некий код, который использует `ActiveRecord::Associations::Preloader` для кастомной подгрузки ассоциации (выборочный `select`). Отлаживаю его в консоли:
```ruby
products_scope = Product.select(:id, :name)
ActiveRecord::Associations::Preloader.new(records: line_items, associations: :product, scope: products_scope).call
```

На проде можно предварительно для удобства перенаправить в консоль SQL-запросы:
```ruby
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](https://ruby-doc.org/core-3.0.0/TracePoint.html). Он позволяет отлавливать разные типы событий, в том числе события `call`, вызываемые на объекте типа [Method](https://ruby-doc.org/core-3.0.0/Method.html). То есть, таким образом мы можем залогировать вызовы любых методов.

```ruby
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`:
```ruby
trace.disable
calls
=> ["Array#pretty_print got called (~/.rbenv/versions/3.1.2/lib/ruby/3.1.0/pp.rb:366)"]
```

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

```ruby
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`:
```ruby
pp(obj.instance_eval(v))
```

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

```ruby
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"
```