URLs, Filters and the Rails Action Controller

Problem

You have an application for which you would like to log more information than you get from the standard Rails logging facilities.

Solution

Use the around_filter to record the times before and after each action is invoked, and log that information in your database.

First, create a database table to store the custom logging; we’ll call that table action_logs. Here’s a migration to create it:

db/migrate/001_create_action_logs.rb:

  class CreateActionLogs
< ActiveRecord::Migration
    def self.up
      create_table :action_logs do |t|
        t.column :action,     :string
        t.column :start_time, :datetime
        t.column :end_time,   :datetime
        t.column :total,      :float
      end
    end

    def self.down
      drop_table :action_logs
    end
  end

Then create the class named CustomLogger. This class must have before and after methods, which are called before and after each action of the controller that you’re logging. The before method records the initial time; the after method records the time after the action has completed, and stores the initial time, the final time, the elapsed time, and the name of the action in the action_logs table.

app/controllers/custom_logger.rb:

  class CustomLogger

    def before(controller)
      @start = Time.now
    end

    def after(controller)  
      log = ActionLog.new
      log.start_time = @start
      log.end_time = Time.now 
      log.total = log.end_time.to_f -
@start.to_f
      log.action = controller.action_name
      log.save
    end
  end

Next, apply the filter to the actions. Add the following line to the beginning of your controller:

  around_filter CustomLogger.new

Now, when you use your site, you’ll be logging data to the action_logs table in your database. Each log entry (start, finished, and elapsed times) is associated with the name of the method that was executing:

     mysql> select * from action_logs;

id  action  start_time end_time  total

1  index 2006-01-12 00:47:52  2006-01-12 00:47:52  0.011997

2  update_each 2006-01-12 00:47:52  2006-01-12 00:47:54  1.75978

3  update_all  2006-01-12 00:47:54  2006-01-12 00:47:54  0.0353839

4  reverse 2006-01-12 00:47:55  2006-01-12 00:47:55  0.0259092

5  show_names  2006-01-12 00:47:55  2006-01-12 00:47:55 0.0264592

5 rows in set (0.00 sec) 

You can see that the controller is spending a lot of its time in the update_each method; that method is therefore a target for optimization.

Of course, you can do much better than this; you can write a Rails application to display the results or write some other application to analyze the data.

Discussion

around_filter requires that the object passed to it as an argument implement a before and an after method. The CustomLogger class records the current time in its before method. The after method creates a new ActionLog object and records the start and end times as well as the difference between the two. The other filters in Rails allow you to include or exclude the actions of the controller that they apply to. The around_filter doesn’t allow for such granularity and operates on all actions invoked by each request.

To be more specific about what actions the around_filter is applied to, wrap your code so that it executes only when the action matches a particular pattern. Doing this is simple, because the controller.action_name property tells you what action is being called. The following version of the after method shows how you can log only those actions whose names begin with the string update. If the action name doesn’t match this string, after just terminates, without recording any data:

  def after(controller)
    if controller.action_name =~ /^update/
      log = ActionLog.new
      log.start_time = @start
      log.end_time = Time.now
      log.total = log.end_time.to_f - @start.to_f
      log.action = controller.action_name
      log.save
    end
  end

See Also

• Recipe 10.4, “Logging with the Built-in Rails Logger Class”