caboose

A few years ago I wrote a simple addition to ActiveRecord that does two things: it chops out the eager loading "t1_t2 AS foo", and it shows the number of records returned for every query you run against the database. You can view the file here

Today I was profiling a site and wanted to quickly find the slow database queries, but didn't have access to mysql's config directly, so I patched that file above to record all queries over 500ms and save it to a log file. I'll warn you now, it ain't pretty, but it works pretty well.

Here's how it works: First, throw this in a file in config/initializers. I open up the rails abstract adapter

module ActiveRecord
  module ConnectionAdapters
    class AbstractAdapter

And add in a new logger.

        def slow_query; 0.5; end # number of seconds
        def slow_query_logger
          @slow_query_logger ||= Logger.new("log/slow_queries.log")
        end

Ideally of course this would all be configurable.

Next, I copy the logging code out of the latest ActiveRecord, and patch it to return the number of records. This is a bit of a hack, too, but we can either look at "num_rows" from the resultset or the actual size of an array.

              s = result && (result.respond_to?(:num_rows) ? result.num_rows : \
                 (result.respond_to?(:size) ? result.size : 0)) || 0

Finally, I rewrite the actual log method so that it checks the benchmark against our threshold

        def log_info(sql, name, runtime, result_size = 0)
          if runtime > slow_query && slow_query_logger
            slow_query_logger.debug "Slow query: (#{runtime}) [#{result_size}] #{sql}"
          end

And add the number of results to the regular rails log, while snipping out the annoying eager-loading code.

          if @logger && @logger.debug?
            if name =~ /Load Including Associations$/
              sql = sql.scan(/SELECT /).to_s + ' ...<snip>... ' + sql.scan(/(FROM .*)$/).to_s
            end

            name = "#{name.nil? ? "SQL" : name} (#{sprintf("%f", runtime)}) [#{result_size.to_i}]"
            @logger.debug format_log_entry(name, sql.squeeze(' '))
          end
        end

Here's the full file.

module ActiveRecord
  module ConnectionAdapters # :nodoc:
    class AbstractAdapter
      protected
        # todo: config this
        def slow_query; 0.5; end
        def slow_query_logger
          @slow_query_logger ||= Logger.new("log/slow_queries.log")
        end

        alias_method :old_log, :log

        def log(sql, name, &block)
          if block_given?
            #if @logger and @logger.level <= Logger::INFO
              result = nil
              seconds = Benchmark.realtime { result = yield }
              @runtime += seconds
              s = result && (result.respond_to?(:num_rows) ? result.num_rows : \
                 (result.respond_to?(:size) ? result.size : 0)) || 0 
              log_info(sql, name, seconds, s)
              return result
            #end
          else
            log_info(sql, name, 0, 0)
            nil
          end
          # old_log(sql, name) { yield }
        rescue Exception => e
          @last_verification = 0
          message = "#{e.class.name}: #{e.message}: #{sql}"
          log_info(message, name, 0)
          raise ActiveRecord::StatementInvalid, message
        end

        alias_method :old_log_info, :log_info
        def log_info(sql, name, runtime, result_size = 0)
          if runtime > slow_query && slow_query_logger
            slow_query_logger.debug "Slow query: (#{runtime}) [#{result_size}] #{sql}"
          end
          if @logger && @logger.debug?
            if name =~ /Load Including Associations$/
              sql = sql.scan(/SELECT /).to_s + ' ...<snip>... ' + sql.scan(/(FROM .*)$/).to_s
            end

            name = "#{name.nil? ? "SQL" : name} (#{sprintf("%f", runtime)}) [#{result_size.to_i}]"
            @logger.debug format_log_entry(name, sql.squeeze(' '))
          end
        end
      end
    end
  end

Would this work as a plugin? As a patch to Rails itself? Or did somebody else already implement a cross-platform slow query logger?