Recipe 4.10. Logging with Filters

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

• Section 10.4"