Rails SQL Logging Improvements

The logging system built into rails works pretty well out of the box. The development.log file contains timing information, SQL statements, and error traces. I especially like the ANSI color coding, which makes the file much easier to eyeball. Still, there is room for improvement. Here are a few changes I’ve made to my Rails logging setup while working on Urbanspoon.

In a future post maybe I’ll discuss how these stats exposed problematic pages. Several pages were transferring 20x more SQL data than needed. :include may be considered harmful.

Logging SQL bytes transferred per page

ActiveRecord is an interesting beast. It’s very easy to use, but doesn’t provide much in the way of caching. Associations can be eagerly loaded using :include, but how does this affect performance? Timing benchmarks are the ultimate arbiter, but I often want to know other statistics. How many queries (SQL roundtrips) did it take to render this page? How many SQL bytes were transferred for this page?

If you plug this snippet in verbatim, you will start seeing a few changes in your log files. First, each SQL select will be followed by a line that reads 21 rows, 8.3k to indicate how many rows/bytes were transferred for the select. Second, the familiar ActionController timing statements will include the number of SQL bytes transferred:

Completed in … | Rendering: … | DB: 0.01312 (3%) 23.6k | …

A few things to note while reading this code:

  • SQL statistics are only turned on for the development environment.
  • It only works for mysql, though I’m sure the same technique can be used for the other adapters.
  • Minor fudging… I’m reporting “string bytes returned by mysql select”, not actual bytes transferred on the wire. If anyone has a suggestion for a simple way to get at the latter I’m all ears.
  • As always with mixins, this isn’t guaranteed to work with all versions of Rails. I’m using 1.1.6.

Add this code to environment.rb:

# only run this code in development
if ENV['RAILS_ENV'] == 'development'

  # modify MysqlAdapter to track transfer stats
  class ActiveRecord::ConnectionAdapters::MysqlAdapter
    @@stats_queries = @@stats_bytes = @@stats_rows = 0
    
    def self.get_stats
      { :queries => @@stats_queries,
        :rows => @@stats_rows,
        :bytes => @@stats_bytes }
    end

    def self.reset_stats
      @@stats_queries = @@stats_bytes = @@stats_rows = 0
    end
    
    def select_with_stats(sql, name)
      bytes = 0
      rows = select_old(sql, name)
      rows.each do |row|
        row.each do |key, value|
          bytes += key.length
          bytes += value.length if value
        end
      end
      @@stats_queries += 1
      @@stats_rows += rows.length
      @@stats_bytes += bytes
      @logger.info sprintf("%d rows, %.1fk", rows.length, bytes.to_f / 1024)
      rows
    end
    
    alias :select_old :select
    alias :select :select_with_stats
  end

  # modify ActionController to reset/print stats for each request
  class ActionController::Base
    def perform_action_reset
      ActiveRecord::ConnectionAdapters::MysqlAdapter::reset_stats
      perform_action_old
    end

    alias :perform_action_old :perform_action
    alias :perform_action :perform_action_reset
    
    def active_record_runtime(runtime)
      stats = ActiveRecord::ConnectionAdapters::MysqlAdapter::get_stats
      "#{super} #{sprintf("%.1fk", stats[:bytes].to_f / 1024)}"
    end
  end
end

Adding SQL bytes transferred to your layout

For added fun, add this to the bottom of your application.rhtml layout file. This is a technique we used at Jobster to provide immediate stats to developers.


  

Suppress blob logging

You may have noticed that Rails likes to dump your SQL blobs to the log file. This will quickly cause your log file to balloon to gargantuan proportions. If you’re especially unlucky, you’ll run out of disk space and you might be forced out of business entirely. I recommend you add this to your environment.rb file immediately:

# trim blob logging
class ActiveRecord::ConnectionAdapters::MysqlAdapter
  def format_log_entry(message, dump = nil)
    if dump
      dump = dump.gsub(/x'([^']+)'/) do |blob|
        (blob.length > 32) ? "x'#{$1[0,32]}... (#{blob.length} bytes)'" : $0
      end
    end
    super
  end
end

Again, I’ve only tested this with mysql and rails 1.1.6.

About these ads

3 thoughts on “Rails SQL Logging Improvements

  1. This is a great post, thanks. The blobs are very annoying in the logs, and keeping track of SQL queries would be much easier if it was in the one-line summary rather than having to count the various queries flying by.

  2. Adam, any idea, how to use this in the latest edge rails? The ‘suppress blob logging’ method doesn’t seem to work now.

  3. Hi Nilesh. Sorry, I haven’t tried this on edge rails yet. Let me know if you find a solution and I’ll post it here.

Comments are closed.