Advanced Rails Debugging

This post follows up on Ruby Debugging Basics

Active Record Query Trace — brunofacca/active-record-query-trace

An excellent gem that’s still a non-optional workhorse in my development practice – especially when debugging a legacy codebase. This gem will display for ALL of your SQL queries where in your Ruby or Gem code the active record update commands are coming from.

Follow the instructions in the Gem to create an initialize file and set it up. My only tip here that adds to the docs is that you’ll want to set the number of lines: ActiveRecordQueryTrace.lines = 10

When debugging a problem in my own Rails app I want this set to a lower number (like 5 or 10). When debugging a problem in Gem code or in Rails I need this at a much higher number (like 50 or 100).

Bullet — flyerhzm/bullet

Understanding N+1 queries is a significant litmus test that sets amateurs from the professionals. Bullet is like a magic bullet – literally named so. It finds your N+1 queries.

Bullet is a great gem that you should install in either development or test, not in production. Because it adds overhead to your speed, install it but leave it configured so that it is turned off by default. Any developer on the team who needs it can turn it on.

You CAN and SHOULD turn it on periodically too, to examine where your app is producing N+1 queries.

Here’s the catch with Bullet. Active Relation creates queries as chains of conditions before it translates that to and executes SQL. That’s why when you do this you must carefully consider query = Country.where(name: "United States")

When you do this in your Rails console, you will see it run the SQL right away.

2.4.6 :039 > Spree::Country.where(name: "United States")
 Spree::Country Load (0.7ms) SELECT `spree_countries`.* FROM `spree_countries` WHERE `spree_countries`.`name` = 'United States' LIMIT 11

N1_Loader — djezzzl/n1_loader

Here an alternative to Bullet also for dealing with N+1 queries. It seems to the “new kid on the block.” and

The ActiveRecord Observer Effect

It only does this because of the ‘print’ effect the Rails console has on your objects. If you string another .where onto this object, when translated into SQL, ActiveRecord will combine the queries: query = Spree::Country.where(name: “United States”); query.where(iso: “US”);
 Spree::Country Load (1.0ms) SELECT `spree_countries`.* FROM `spree_countries` WHERE `spree_countries`.`name` = ‘United States’ AND `spree_countries`.`iso` = ‘US’ LIMIT 11

The reason this is important is that to understand where your N+1 queries are coming from you need to understand when you created when you invoked them. They are not the same place, although on the Rails console it makes you think it is one and the same. When you grok this, you will see why Active Record’s side loading (which loads a related set of objects in a single optimized query, taking the number of queries from N+1 to 1+1=2) is both efficient and can be tricky to work with, especially with objects that have many relationships.

Don’t be fooled: Side-loading is nearly always more efficient than N+1 queries. 

Bullet tells you where those pesky N+1 queries are invoked, but not where you are creating them. What you then need to do is trace your code (manually) to figure out where the queries are being created. Hopefully, this should be near in the code to where they are being invoked (but in the case of complex filtering logic might not be).

Here you need to add the appropriate .joins(:____) to your code anywhere between when you set up the objects and when Active Record invokes them. Note that you’ll only want to join in those additional tables if you actually use them. If not, you don’t need the overhead.

You’ll know you’ve solved your N+1 queries because you won’t see them output in your Rails log, and they’ll disappear from the Bullet code.

Introspect, Introspect, Introspect but remember Ruby’s last-line quirk

Always look at what you’re doing. Drop into your debugger>. Look at your variables. Clone & freeze them. Look for race conditions, Look for flip-floppers. Watch out for your own confirmation bias.

Remember that when in the debugger or on the Rails console and you type a SINGLE VARIABLE and HIT RETURN, the console will interpret that action as-if you had called .inspect

2.2.5 :007 > a
=> #<Apple id: nil, created_at: nil, updated_at: nil>
2.2.5 :008 > a.inspect
=> "#<Apple id: nil, created_at: nil, updated_at: nil>"

observer effect” in software development

In some cases, the act of inspection actually changes the object (like in the case of an Active Relation, in which case it invokes the query), so keep that in mind. (We might call this the “observer effect” in software development.)