One of my current projects involves significantly improving the search function in a Rails application, a thorny problem that led me to come up with the method to quiet down the Rails logger in my SQL log silencer. It turns out, that wasn’t enough. I have expanded quite a bit on that idea by folding in some useful debugging aids from other developers, making them more useful, and adding a SQL query “hit list” after each request completes. I’m releasing it as the sql_logging plug-in.

Installation is the usual (on one line):

$ script/plugin install \
http://svn.lightyearsoftware.com/svn/plugins/sql_logging


I have set up a forum for discussion and support of the plug-in.

So, what does this give you?

Out of the box, you get these new things:

• A count of the number of rows returned and a rough count of bytes for each SELECT query
• A summary at the end of the request of the total number of queries, bytes returned and SQL executions
• Each SQL execution includes a clean-up backtrace to show you exactly what part of your code triggered the query
• A summary at the end of the request showing a “top 10″ list of queries

The last one is particular useful. Queries are grouped by their backtrace, and then sorted by either number of executions, rows returned or bytes returned. This provides an excellent way to target your performance optimization work.

When sorted by executions, you very quickly see where the same code is triggering a query over and over, and can spend your optimization time trying to reduce this by adding the model to an earlier query (via :include) or by getting more rows at a time by batching up loads (WHERE id IN (…)). Here’s a sample:

Completed in 13.01586 (0 reqs/sec) | Rendering: 2.69928 (20%) | DB: 8.68216 (66%), 154 selects, 1728.1 KB, 166 execs
Top 10 SQL executions:
  Executed 95 times, returning 180 rows (230.5 KB):
    app/models/merge_keyword.rb:34:in `get_merges_by_keyword'
    app/models/merge_keyword.rb:30:in `each'
    app/models/merge_keyword.rb:30:in `get_merges_by_keyword'
    app/models/merge.rb:107:in `search'
    app/models/merge.rb:105:in `each'
    app/models/merge.rb:105:in `search'
    app/controllers/search_controller.rb:98:in `results'
  Executed 22 times, returning 30 rows (1.3 KB):
    app/models/merge.rb:80:in `attribute'
    app/views/merges/_result_line.rhtml:2:in `_run_rhtml_47app47views47merges47_result_line46rhtml'
    app/views/search/results.rhtml:172:in `_run_rhtml_47app47views47search47results46rhtml'
    app/views/search/results.rhtml:170:in `each'
    app/views/search/results.rhtml:170:in `each_with_index'
    app/views/search/results.rhtml:170:in `_run_rhtml_47app47views47search47results46rhtml'
  Executed 20 times, returning 30 rows (1.2 KB):
    app/models/merge.rb:80:in `attribute'
    app/helpers/application_helper.rb:40:in `merge_detail_link'
    app/views/merges/_result_line.rhtml:26:in `_run_rhtml_47app47views47merges47_result_line46rhtml'
    app/views/search/results.rhtml:172:in `_run_rhtml_47app47views47search47results46rhtml'
    app/views/search/results.rhtml:170:in `each'
    app/views/search/results.rhtml:170:in `each_with_index'
    app/views/search/results.rhtml:170:in `_run_rhtml_47app47views47search47results46rhtml'

By sorting by rows or bytes returned, you may be able to determine that you need to let the database do more of the filtering work. It may be inefficient to have the database return a pile of rows to your application, only to discard a bunch of them.

The silencer from my previous post is in there, too, along with a new silencer that quiets only the backtrace for the duration of the block:

silence_sql do
  # ...
end
 
silence_sql_backtrace do
  # ...
end

I must give a big hat tip to Adam Doppelt and Nathaniel Talbott. Adam’s SQL logging enhancements formed the basis for the logging enhancements here. I made them a little more generic so they worked with both MySQL and PostgreSQL, as well as tracking executions for things that don’t return data. Nathaniel’s QueryTrace plug-in has been around for a while, and I originally tried making this new plug-in simply work with it, but in the end decided to fold the functionality in so the “top 10″ list didn’t duplicate the backtrace cleaning code. I also added a regexp to the cleaner so it excludes the plug-in’s code from the backtrace.

There are a few more goodies in the plug-in, so look at the README for more details.

Update: I fixed a few bugs and added a feature. The plug-in now ignores queries whose name ends with ” Column”. These are internal Rails queries and their inclusion skewed the results.

The new feature tracks the execution time of SQL, and lets you sort the top-10 list by either total time for all instances of the SQL or the median execution time. Total time is also now the default sorting method, as this is probably the best way to attack SQL optimization: whatever is taking up the biggest percentage of your time in the database is a good place to start.

Update 2: The plug-in works on Rails 2.0.2 now.

Here’s something I just whipped up to quiet ActiveRecord’s logging in development mode. Normally, ActiveRecord’s AbstractAdapter logs every SQL query as it is made. Sometimes, it’s nice to quiet this down without changing your log level while tracking down a problem.

class ActiveRecord::ConnectionAdapters::AbstractAdapter
  def log_info_with_silencing(sql, name, runtime)
    unless ActiveRecord::Base.silence_sql_logging
      log_info_without_silencing(sql, name, runtime)
    end
  end
 
  alias_method_chain :log_info, :silencing
end
 
module SqlSilencer
  def silence_sql
    logging = ActiveRecord::Base.silence_sql_logging
    begin
      ActiveRecord::Base.silence_sql_logging = true
      yield
    ensure
      ActiveRecord::Base.silence_sql_logging = logging
    end
  end
end
 
class ActiveRecord::Base
  @@silence_sql_logging = false
  cattr_accessor :silence_sql_logging
 
  include SqlSilencer
end
 
class ActionController::Base
  include SqlSilencer
end

Drop this into a file in config/initializers if you’re on Rails 2.0 or require it from within environment.rb for pre-2.0.

To use inside a controller action or model method, simply wrap the code you want to silence inside a block:

def index
  silence_sql do
    # lots of work here...
  end

One interesting side effect of this is that you can easily see how much database work is done as a result of what’s in your view. Wrap the entire controller action inside a silence_sql block, then look at your log. Any queries you see are a result of things you didn’t load in the controller.

Chronic is a nice natural language parser for Ruby, but my first stab at adding it to a Rails application immediately felt wrong. I was adding special case code in a controller to re-parse the field if the initial parse failed. Of course, that needed to be duplicated for every field I wanted to support it.

A much better (second) idea was, why not add this directly to ActiveRecord? Every model gets it for free, and it turns out the code is hardly any more complicated.

require 'active_record'
require 'chronic'
 
module ChronicParser
  def self.extended(object)
    class << object
      alias_method_chain :string_to_date, :chronic
      alias_method_chain :string_to_time, :chronic
    end
  end
 
  def string_to_date_with_chronic(string)
    value = string_to_date_without_chronic(string)
    if value.nil?
      now = TzTime.now rescue Time.now
      value = Chronic.parse(string, :now => now).to_date rescue nil
    end
 
    value
  end
 
  def string_to_time_with_chronic(string)
    value = string_to_time_without_chronic(string)
    if value.nil?
      now = TzTime.now rescue Time.now
      value = Chronic.parse(string, :now => now)
    end
 
    value
  end
end
 
ActiveRecord::ConnectionAdapters::Column.extend(ChronicParser)

Put this where it will be executed during Rails initialization and you’re done.

Note also that while Chronic doesn’t claim to support time zones, this code will do the right thing by supplying a local perspective of the user’s current time, using TzTime. Someone in Japan using your site (which is hosted in California) in the early morning will get the expected result for “tomorrow.”

If a zone hasn’t been set for TzTime, it’ll fall back on the server’s current time. If you aren’t using TzTime, modify appropriately.

If you use RESTful routes and define custom actions for your resources, you might suddenly find your custom action don’t work after upgrading to 1.2.4. Whereas this used to work fine in 1.2.3:

map.resources :users
map.resources :users, :collection => { :signin => :any,
                                       :signout => :post,
                                       :forgot_password => :any,
                                       :welcome => :get }
map.resources :member => { :email => :get,
                                     :prefs => :get,
                                     :close => :post }

This is actually wrong, and creates duplicate entries in the routing table. The symptom of this problem is that your custom actions (e.g. /users/signin) will run the show action with a bogus ID of signin.

The proper way to define these resource routes is in one shot:

map.resources :users, :collection => { :signin => :any,
                                       :signout => :post,
                                       :forgot_password => :any,
                                       :welcome => :get },
                      :member => { :email => :get,
                                   :prefs => :get,
                                   :close => :post }

(Thanks to wolfmanjm on the rubyonrails-talk list for posting and answering his own question, as I was having the exact same problem.)

The Rails core team released a small update to the 1.2 stable branch last week, 1.2.4, which fixes a few potential security problems and offers some minor enhancements.

If you plan to move your application to 2.0 when it’s released, the 1.2.4 update turns on some additional deprecation warnings that will help point out potential trouble in your existing code. Another useful resource for this is Mislav Marohnić’s compatibility checker script, though be forewarned that it may return false positives, since it’s just doing regular expression matches.

rake routes, previously available on edge, is included. This will show you all of your named routes, in match order, which makes debugging route-related issues much easier. (You can do this prior to 1.2.4, too, but that requires installing sake and the routes sake recipe.)

For me, though, by far the most welcome enhancement in the 1.2.4 update is something I’ve had to live with since starting to use Google Analytics: Analytics doesn’t know how to handle a semicolon in a goal URL. If you use RESTful routing and display a “thank you” page when a resource (say, an order) is successfully created, chances are high that you won’t be able to track this as a goal in Analytics. This is because custom actions for resources used a semicolon to separate the action from the rest of the path. 1.2.4, just like the coming 2.0, changes this to a regular slash, to avoid incompatibilities with software, such as Analytics, that mistake the semicolon as part of the query string.

If for some reason you want the old behavior, you’re in luck, as the choice of separator is now a class-level accessor on ActionController::Base:

ActionController::Base.resource_action_separator = ';'  # or whatever

When a form in your Rails application is used to edit (or create) an ActiveRecord instance, ActionView uses the ActiveRecordHelper module to create the HTML input field tags. In the event of an error, your input field is wrapped inside a DIV with class=”fieldWithErrors”. This isn’t so bad, but you’re left with few options for customizing the look of your forms when there is an error. For example, what if you wanted to put the error text associated with a field right next to the field?

One way to do this is by putting additional markup in your forms. Something like:

<% if object.errors.on(:some_field) %>
  <span class="error"><%= object.errors.on(:some_field) %></span>
<% end %>
... rest of field markup ...

That works, but you have to repeat the fields at least twice: once for the potential error condition, and once for the field itself.

You could write up a new form helper that includes the boilerplate error markup, but that falls apart as soon as you want to put in a set of checkbox or radio button controls. Maybe you only want one error message for the entire group, which is almost certainly true for radio buttons.

Another alternative that I don’t see widely acknowledged is to override the standard Proc used by the ActiveRecordHelper for errors: ActionView::Base.field_errro_proc. Here’s an example:

ActionView::Base.field_error_proc = Proc.new do |html_tag, instance|
  error_text = ""
  errors = instance.object.errors.on(instance.method_name)
  if errors
    errors.to_a.each do |error|
      error_text << "<p class=\"error\">#{error}</p>"
    end
  end
  "<div class=\"errors\">#{error_text}</div>#{html_tag}"
end

The Proc instance is passed the HTML tag (already built into a string) and an instance of InstanceTag. The latter is the class used by many of the ActionView helpers for building HTML tags that correspond to a particular piece of data in an object. InstanceTag keeps a reference back to that object and method, and you can make use of it in your custom field_error_proc, as shown above.

One little annoyance you don’t see until you start down this path is that the method that builds checkboxes always includes a hidden field with the same name. This is done to ensure that some value for that field is always sent to the server when the form is submitted. The trouble is that the hidden field gets no special treatment from ActiveRecordHelper: field_error_proc is called twice, once for the checkbox field and once for the hidden field, and custom error messaging, as shown above, gets rendered twice. This can be fixed by overriding InstanceTag#tag:

def tag(name, options)
  if object.respond_to?(:errors) && object.errors.respond_to?(:on)
    suppress_errors = (name == "input" && options["type"] == "hidden")
    error_wrapping(tag_without_error_wrapping(name, options),
                   object.errors.on(@method_name) && !suppress_errors)
  else
    tag_without_error_wrapping(name, options)
  end
end

A couple of people have asked how to achieve the results I showed off in my posting about the pgsql_stats plug-in. I just posted an example use page on the pgsql_stats Google Group that shows the controller and view code used to create that screenshot. Enjoy!

A while back, I ran across sparkline graphs, created by Edward Tufte for displaying data visually in a very compact space, usually inline with text. Google uses these extensively in their Analytics product, and it seemed like a great fit for representing data on the ZingLists administrative dashboard.

There are two easily found implementations of sparkline graphs for Ruby: Sparklines and Bumpspark. Bumpspark is nice because the graphs use data: URIs and don’t require any extra parts server-side, but the Sparklines plugin offers far more drawing options.

Why not the best of both? Here is a modified sparkline_tag method for Sparklines, which accepts a new option, :inline_data. When true, it emits a data: URI instead of a reference back to your server. I like this for several reasons: it loads faster, it doesn’t require a new controller, and it doesn’t require a new route if you’ve done away with the generic /:controller/:action/:id and are using RESTful routes.

require 'base64'
 
  def sparkline_tag(results = [], options = {})
    tag_options = { :class => (options[:class] || 'sparkline'),
                    :alt => "Sparkline Graph" }
    if options.delete(:inline_data)
      tag_options.merge!(:src => "data:image/png;base64,#{Base64.encode64(Sparklines.plot(results, options)).gsub("\n", "")}")
    else
      url = { :controller => 'sparklines', :results => results.join(',') }
      tag_options.merge!(:src => url_for(url.merge(options)))
    end
    tag(:img, tag_options)
  end

Update: When I emailed this to Geoff (who maintains Sparklines), he reminded me that IE doesn’t support data: URIs, so :inline_data isn’t useful if your pages need to display in IE.

The PostgreSQL database includes a statistics collection facility that can give you information about your database, tables, indexes and sequences. I just posted a new Rails plug-in that makes it very easy to gather this information and display it in a Rails application.

All of the counters described in the PostgreSQL manual are represented in the models in the plug-in. To name a few:

• Number of scans over the table or index
• Cache hit/miss counters (and cache hit rate, by a simple computation)
• On-disk size

In the above screenshot (taken very soon after the server was started), it’s easy to see that the cron_runs table is by far the largest in the database, followed by its primary key index. Of the entities that have been touched, a large percentage of requests are being satisfied by the buffer cache. You can’t see it in that image, but I’ve defined ranges that turn the green bars red if the cache hit rate falls below 75%.

I’ve set up a Google Group forum for further discussion. Some additional information is available in the README, and the plug-in can be installed like any other:

$ script/plugin install \ http://svn.lightyearsoftware.com/svn/plugins/pgsql_stats

All on one line, of course.

Update Sep. 10, 2007: There is now a usage example on the Google Group that shows how to get the results shown in the screenshot.

Update Jul. 23, 2008: Part of the fallout of Google disabling my account appears to be that the group I set up for discussion and support disappeared, too. I have moved discussion and support to my own forums: pgsql_stats forum.

One of the few times Rails let me down while developing ZingLists was how it deals with class inheritance in ActiveRecord. Actually, unless you want Single-Table Inheritance semantics, you may as well pretend it doesn’t exist, because I couldn’t find a clean way to do it.

Here was my particular problem:

Out of the box, Rails likes to construct URLs that usually end with a numeric ID when you’re dealing with resources. There is a method, to_param, that the URL helpers call when they want to turn an object into an ID suitable for a URL.

Conventional wisdom says that Google likes URLs that are meaningful. A string of numbers at the end doesn’t mean anything, which is why you often see URLs ending with a snippet from the page title. Blogs often do this (just look at the top of this page, if you’re not reading from the index).

So, to get nice URLs, modify to_param. But what if you only want to do it some of the time? Inheritance usually solves this problem: customize in the derived class. But ActiveRecord forces STI on you if you do this, and maybe you don’t want that.

In ZingLists, I have a single table, lists, that contains all of the lists in the system, whether they are private lists for a member or lists that a member has published to the community. It pretty much has to be this way, since publishing a list does not fix it in time. The member may (and probably will) continue to use it for themselves, and if they add to it, I’d like those changes to be available in the public view immediately, with no extra work.

I want public list URLs to be nice for Google, but don’t have any desire to junk up private list URLs, too. How to solve this problem?

Duck Typing. The URL helpers don’t care what kind of class you hand them, as long as it responds to to_param:

class PublicList
  def initialize(list)
    @list = list
  end
 
  def to_param
    "#{@list.id}-#{@list.name[0..29].tr_s(" ", "-").gsub(/[^-a-z0-9]+/i, "")}"
  end
end

Now, when I want to create a pretty URL for Google’s benefit, I just have to instantiate a wrapper around the real object:

public_list_path(PublicList.new(list))

(Wishful thinking: What would be really neat is a facility where you can get STI-like semantics, but provide your own definition of how to differentiate between the types of object, rather than have it hard-coded to a column called “type” that contains a string representation of the class to instantiate.)