TracePoint and Rails reload! / startup

On a specific rails application (4.2), when a developper call reload! method on a console he'll see:

Engine Load (0.3ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'influencer' LIMIT 1
Engine Load (0.3ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'speaker' LIMIT 1
Engine Load (0.3ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'animator' LIMIT 1
Engine Load (0.2ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'ambassador' LIMIT 1
Engine Load (0.2ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'private_show' LIMIT 1
Celebrity Load (74.6ms)  SELECT `celebrities`.* FROM `celebrities`  ORDER BY first_name ASC
Celebrity Load (74.6ms)  SELECT `celebrities`.* FROM `celebrities`  ORDER BY first_name ASC
Agency Load (35.5ms)  SELECT `agencies`.* FROM `agencies`  ORDER BY family_name ASC

How to know from where this queries have been called? This is a solution to find it, I assume there is a lot of other ways to deal with this.

Tracepoint

A class that provides the functionality of Kernel#set_trace_func in a nice Object-Oriented API. In other words a wonderfull tool to debug.

With TracePoint, ruby can tell you what is doing.

Example

#trace_add.rb
trace = TracePoint.new do |tp|
  p tp
end

trace.enable
[2, 1, 3].count
trace.disable

# => #<TracePoint:c_return `enable'@trace_count.rb:6>
# => #<TracePoint:line@trace_count.rb:7>
# => #<TracePoint:c_call `count'@trace_count.rb:7>
# => #<TracePoint:c_return `count'@trace_count.rb:7>
# => #<TracePoint:line@trace_count.rb:8>
# => #<TracePoint:c_call `disable'@trace_count.rb:8>

First two line concern trace generation. After that we have a :c_call followed by a :c_return which is a return from the count method, defined in C code, then lines for disabling trace.

With TracePoint It's possible to filter events

Availables events

:line - execute code on a new line
:class - start a class or module definition
:end - finish a class or module definition
:call - call a Ruby method
:return - return from a Ruby method
:c_call - call a C-language routine
:c_return - return from a C-language routine
:raise - raise an exception
:b_call - event hook at block entry
:b_return - event hook at block ending
:thread_begin - event hook at thread beginning
:thread_end - event hook at thread ending
:fiber_switch - event hook at fiber switch

Available methods used to debug

event - type of event
inspect - Return a string containing a human-readable TracePoint status.
lineno - Line number of the event
method_id - Return the name of the method being called
path - Path of the file being run
raised_exception - Value from exception raised on the :raise event
return_value - Return value from :return, c_return, and b_return event
self - Return the trace object during event

#trace_add.rb
trace = TracePoint.new do |tp|
  p [tp.lineno, tp.defined_class, tp.method_id, tp.event]
end

trace.enable
[2, 1, 3].count
trace.disable

# => [6, TracePoint, :enable, :c_return]
# => [7, nil, nil, :line]
# => [7, Array, :count, :c_call]
# => [7, Array, :count, :c_return]
# => [8, nil, nil, :line]
# => [8, TracePoint, :disable, :c_call]
end

The main issue with TracePoint is that you can't use it with IRB or Pry because it REPL have making a lot of calls that hide real calls.

Debug a rails call without Rails console

There it is the first difficulty, how to call reload! without a console ? This is reload! source code

# File railties/lib/rails/console/app.rb, line 25
def reload!(print=true)
  puts "Reloading..." if print
  ActionDispatch::Reloader.cleanup!
  ActionDispatch::Reloader.prepare!
  true
end

I opened a console and called both methods. It seems that ActionDispatch::Reloader.prepare! make the queries.

Rails runner

Rails offers runner which runs Ruby code in the context of Rails non-interactively. For instance:

$ rails runner "Model.long_running_method"
```

In our case we want to execute a script like this one:

```rb
trace = TracePoint.new do |tp| 
  Rails.logger.debug tp.inspect.to_s
end
trace.enable

ActionDispatch::Reloader.prepare!
trace.disable'
```

And with the runner:
```sh
rails runner 'trace = TracePoint.new {|tp| Rails.logger.debug tp.inspect.to_s };trace.enable;ActionDispatch::Reloader.prepare!;trace.disable'
```

**Note: Use this command will generate more than 2Gb of data log.**

Before to use it be aware to empty development.log.

### Filter log file
Finally we have all needed data, there is only one to do: filter.

I assume all these requests are created by Rails application, therefore I decide to keep all files present in app directory and a part of a query which is logged by the logger.

```sh
grep -e "/Users/Yann/code/brand_engine/app/" -e"\`celebrities\`" development.log > tmp.log
```

Now I search the query and the line before:

```sh
grep -B 1 "\`celebrities\`" tmp.log

# => #<TracePoint:line@/Users/Yann/code/brand_engine/app/admin/posts.rb:50>
# =>   Celebrity Load (71.6ms)  SELECT `celebrities`.* FROM `celebrities`  ORDER BY first_name ASC
```

### Results

File: **app/admin/posts.rb:50**

```rb
filter :celebrity_id,
         as: :select,
         collection: Celebrity.order('first_name ASC').collect { |celebrity| ["#{celebrity.first_name} #{celebrity.family_name}", celebrity.id] }
```
Log: `Celebrity Load (74.6ms)  SELECT `celebrities`.* FROM `celebrities`  ORDER BY first_name ASC`

File: **app/admin/tweets.rb:93**

```rb
filter :celebrity_id,
         as: :select,
         collection: Celebrity.order('first_name ASC').collect { |celebrity| ["#{celebrity.first_name} #{celebrity.family_name}", celebrity.id] }
```
Log: `Celebrity Load (74.6ms)  SELECT `celebrities`.* FROM `celebrities`  ORDER BY first_name ASC`

File: **app/admin/project_roots.rb:74**

```rb
filter :agency_id,
         as: :select,
         collection: Agency.order('family_name ASC').collect { |agency| ["#{agency.reverse_full_name}", agency.id] }
```
Log: `Agency Load (35.5ms)  SELECT `agencies`.* FROM `agencies`  ORDER BY family_name ASC`

File: **app/models/celebrity_notation.rb:37**

```rb
ENGINES = [Engine.find_by(label: 'influencer'), Engine.find_by(label: 'speaker'), Engine.find_by(label: 'animator'), Engine.find_by(label: 'ambassador'), Engine.find_by(label: 'private_show')]
```

Log: 

```
  Engine Load (0.3ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'influencer' LIMIT 1
  Engine Load (0.3ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'speaker' LIMIT 1
  Engine Load (0.3ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'animator' LIMIT 1
  Engine Load (0.2ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'ambassador' LIMIT 1
  Engine Load (0.2ms)  SELECT  `engines`.* FROM `engines` WHERE `engines`.`label` = 'private_show' LIMIT 1
```

yannvery/tracepoint_and_rails_reload!.md