Improve your slow-queries

Good ORMs are handy: they avoid boilerplate without dictating what is possible and what is not. In most case you don’t even need to have a look at the SQL they generate (as long as you test your code).

But sometimes things goes wrong: during a stress test — or even in production — a bad query happen that takes a long time to execute.

You get the culprit in your slow query log, but here’s the catch: sometimes you can’t figure what part of the code is generating the query, or there’s several candidates and you don’t want to loose to much time figuring how’s the troublemaker.

To make things easier, you need to realize two things:

you can add comments in your SQL
you can automate it
you can use it to know what is generating the query
PROFIT!!

The basic idea is to instrument your code so the query contains an indication of the query origin.

Example: in a web application, you can prefix queries with the current URL, in most cases it should be good enough.

Depending of your language and ORM, it may be as easy as finding the right hook or it could require some dirty tricks.

An example in Ruby / Sinatra / Sequel, where you need to be tricky:

app.rb

require 'sinatra/base'
require 'sequel'
require 'logger'
require 'sequel/database'

module Sequel

  # We'll monkey patch it since I didn't find a cleaner way to do it.
  class Database

    # Alias a method so we can override it
    # but still call the original
    alias :log_connection_yield_old :log_connection_yield

    # This method is called for each query
    # so we can use it to patch the query
    def log_connection_yield(sql, conn, args=nil, &block)
      # Can't patch the frozen Strings,
      # but as the frozen queries are used to create the connection
      # it's not a problem
      unless sql.frozen?
        # Prepend the current path
        sql.prepend("/* This query comes from [#{Thread.current[:current_sinatra_path]}] */ ")
      end
      # call the original
      log_connection_yield_old(sql, conn, args, &block)
    end

  end
end

class App < Sinatra::Base

  DATABASE = Sequel.sqlite(
    '',
    :loggers => [Logger.new(STDOUT)]
  )

  # Hook called before each call
  # Set the current path to be able to retrieve it
  before do
    # Initialize the thread local variable
    Thread.current[:current_sinatra_path] = request.fullpath
  end

  # This is my service, you'll be impressed
  get '/date' do
    # Simple query that doesn't need any table
    DATABASE.fetch('SELECT date(?) as d', 'now').first[:d]
  end

end

In the query log:

/* This query comes from [/date] */ SELECT date('now') as d

If your code is really complicated or messy, you can increase the level of detail: if you want you can even add the complete stacktrace! It would turns your logs into an horrible thing, but sometimes desperate times call for desperate measures, and you can make it togglable at runtime.