How to Log Which Line Initiated a Query in Rails

Create a file (something like) config/initializers/active_record_log_subscriber.rb

…and paste this into its contents:

module LogQuerySource
  def debug(*args, &block)
    return unless super

    backtrace = Rails.backtrace_cleaner.clean caller

    relevant_caller_line = backtrace.detect do |caller_line|
      !caller_line.include?('/initializers/')
    end

    if relevant_caller_line
      logger.debug("  ↳ #{ relevant_caller_line.sub("#{ Rails.root }/", '') }")
    end
  end
end
ActiveRecord::LogSubscriber.send :prepend, LogQuerySource

Now, whenever a line of code initiates a SQL query the line will be logged.  This greatly improves the ease of tracking down inefficiencies such as like N + 1 queries.

If you would like to learn more about exactly how this mix-in works and how the original author went about figuring out how to add it, you can read more about it here.

 

Commenting and Documentation in Ruby and Rails

It’s always been frustrating to me that Ruby and Rails don’t really have strong templated standards on how to best document your code. There are several options available and it can all be very confusing and unclear.

There is one template I’ve found works best and its super simple:

# Brief explanation of what the code does.
#
# * *Args* :
# - ++ ->
# * *Returns* :
# -
# * *Raises* :
# - ++ ->
def my_method

end

While there are many other perfectly good documentation libraries this has the benefits of being simple to remember, very easy to read in code, and compiles out super nicely using

rake doc:app

Example (strongly based off this post):

# This is an example method commented the way I 
# like. It sums the three arguments and returns 
# that value.
#
# Lorem ipsum dolor sit amet, consectetur adipising,
# do eiusmod tempor incididunt ut labore et dolore. 
# Ut enim ad minim veniam, quis nostrud exercit
# laboris nisi ut aliquip ex ea commodo consequat.
#
# * *Args* :
#   - +apples+ -> the number of apples
#   - +oranges+ -> the number of oranges
#   - +pears+ -> the number of pears
# * *Returns* :
#   - the total number of fruit as an integer
# * *Raises* :
#   - +ArgumentError+ -> if any value is nil or negative
def sum_fruit(apples, oranges, pears)
  ...
end

Will render into something like this:


Other than this, I tend to try and follow the general conventions as outlined by the Rails contribution guidelines on commenting.

NotImplementedError Must Have Battered Wife Syndrome

I’ve been doing something very wrong my whole life.  I think it’s time to confess and seek help.

You see, like so many developers I see the NotImplementedError class in various languages and think, to my self “I haven’t had a chance to fully implement this class, so in my methods that my colleagues call that I didn’t finish yet, I will raise that exception to let them know.”

I am ashamed of myself.  And it’s time to get help.

You see the actual purpose of the NotImplementedError (as defined by the Ruby docs) is:

Raised when a feature is not implemented on the current platform. For example, methods depending on the fsync or fork system calls may raise this exception if the underlying operating system or Ruby runtime does not support them.

ERMERGERD!  I am a terrible person. Abusing this error class just because  my sub classes cannot meet the contractual obligation of the super class.

And I know I am not alone.

So whats the best practice, then?

Well, in Ruby’s case it turns out the answer is super simple; don’t raise an error at all! Instead, document the expectation and if a subclass fails to meet it a NameError, or often its subclass NoMethodError, will be raised automatically.

 

How to manually mark ActiveRecord attribute as dirty

Recently I had quite a conundrum. I was working on a project’s model that was using the ActiveRecord save method update_columns to avoid executing the callbacks on the model, however had the unexpected side-effect further down my stack when a method in the chain checked if a particular attribute changed, wasn’t working because as well as skipping validations and callbacks; it also bypasses the ActiveModel::Dirty logic!

This caused me quite a problem, as I feared that I would be forced to use a method of saving the record that triggered my callbacks (very undesirable).

Fortunately, there is a solution.  Because the ActiveModel::Dirty class is still loaded, you can manually mark with attributes are dirty by simply calling [attr_name]_will_change! before the change to track the attribute.

attribute_name_will_change!

Normally this is all done for you and now later on in the stack when you do something like

if attribute_name_changed?
  was = attribute_name_was
end

It will work, despite using a method to save that doesn’t automatically track the dirty attributes for you.

Actually the ActiveModel::Dirty module has some pretty cool stuff in it. Much of it never gets properly explored in the average Rails project, but it provides some hidden magic, like being able to fully revert an object and undo a save, providing a kind of diff of changes and some other really neat stuff.

A better way to benchmark

Today I found some magic.

include ActiveSupport::Benchmarkable

An ActiveSupport module that provides an AMAZINGLY elegant alternative to the classic Ruby Benchmark class; which I had always considered to be a bit ‘clunky’.

ActiveSupport::Benchmarkable provides you a simple method ‘benchmark’ which you can pass a few options and block through and output the benchmark result to the log. Wrap this block around expensive operations or possible bottlenecks to get a time reading for the operation.

For example, let’s say you thought your data transformattion method was taking too long; you could wrap it in a benchmark block.

<% benchmark 'v' do %>
  <%= expensive_record_transforming %>
<% end %>

That would write something like “Processing some data (143.6ms)” to the log, which you can now use to monitor or compare speed over time (make sure its not getting worse as data size increases) or compared to alternate methods for optimisation.

The ActiveSupport::Benchmarkable docs also indicate that, you may give an optional logger level (:debug, :info, :warn, :error) as the :level option. The default logger level value is :info.

<% benchmark 'Low-level files', level: :debug do %>
  <%= lowlevel_files_operation %>
<% end %>

Finally, you can pass true as the third argument to silence all log activity (other than the timing information) from inside the block. This is great for boiling down a noisy block to just a single statement that produces one log line:

<% benchmark 'Process data files', level: :info, silence: true do %>
  <%= expensive_and_chatty_files_operation %>
<% end %>

while these samples are indicative of what they would look like in a .html.erb file (view) – it also works in any other place you use the mix in.

I have personally used these to great success in controllers and models to help diagnose specific controller/model operations suspected to be slow.

This ActiveSupport module is an immensely powerful tool to have in a developers arsenal. I highly recommend it’s use.

Converting TEXT columns to JSONB in PostgreSQL

Recently I had a text field being used to store JSON data from my web application. I hadn’t yet discovered the amazingness of the PostgreSQL JSONB datatype.

JSONB is an amazing datatype because Postgres understands how to query the structure and the keys and values can be indexed.

So if you have a text fields you want to convert to JSONB (provided the existing data is in properly formed JSON already) You can change the datatype and convert the existing data using this simple SQL command:

alter table tbl_name alter column col_name type jsonb using col_name::JSON;

You may be inclined to covert the text using the to_json function like: ‘USING to_json(col_name);’ – BUT DON’T DO THAT! What happens with that is you get a single string encapsulating the valid JSON, containing your JSON. Effectively a double-encoding bug.  The former (casting the column to JSON is the correct way).