URLs, Filters and the Rails Action Controller - 4.10 Logging with Filters
(Page 3 of 4 )
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
Next: 4.11 Rendering Actions >>
More Ruby-on-Rails Articles
More By O'Reilly Media
|
 This article is excerpted from chapter four of the Rails Cookbook, written by Rob Orsini (O'Reilly, 2007; ISBN: 0596527314). Check it out today at your favorite bookstore. Buy this book now.
|
|
