You’ll all have seen lines like this in your log files:
Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 2.7ms)
While obviously a very high level view of your application’s performance, it’s still a good place to start when you’re wondering where the time has gone. If you’re using a different datastore or if external services (solr, sphinx, external API calls) are important contributors to your application’s performance you might want time spent in those services listed too.
Prior to Rails 3, it was hard to add information to this summary without making a mess of things. What was reported on was just hardcoded into Action Controller. Things are a lot easier in Rails 3.
New in Rails 3 is
ActiveSupport::Notifications. The idea here is to decouple things producing performance data and things consuming them.
1 2 3
will record how long it took to do the task, and then yield that data to anyone interested (instances of subclasses of ActiveSupport::LogSubscriber). Action Controller’s process action is wrapped by a call to instrument and one particular subscriber to that is one that writes what Action Controller has been up toto the app’s log file. If you wanted to analyze your app’s data other than by eyeballing the log files you could write your own class that could subscribe to these notifications and do whatever processing you wanted, instead of writing something to parse your log files.
A simple example
Suppose we want the time we spend query solr to be logged. Following the way Active Record does things, you need to do three things: instrument the action we wish to monitor using ActiveSupport::Notifications, record the information in a subscriber and then plug the resulting data into Action Controller.
At its barest, the instrumentation might look like this
1 2 3 4 5 6 7 8 9 10
send is a funnel through which all queries to solr flow.
The log subscriber might look a little like this:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22
The call to
attach_to means that whenever a
foo.solr event is fired, our subscriber’s
foo method will be called. The only thing we do in our subscriber is keep track of how much time has been spent, using the
reset_runtime resets the counter and returns the time accumulated so far.
The last thing we need to do is use the hooks that Action Controller helpfully provides. The following is lifted pretty much line for line from Active Record:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37
cleanup_view_runtime is used to prevent double counting of time spent performing database queries etc. as both database time and view rendering time. The call to super in
cleanup_view_runtime will wind up actually rendering the view, so looking at the solr time before and after this tells us how much time we need to deduct from the view render time (which is what the call to super returns).
append_info_to_payload is where we record how much time has been used in total, which is the sum of solr time before, during and after rendering the view.
log_process_action (a class method) acts on a payload hash and produces an array of components such as ‘ActiveRecord: 32.2ms’.
Finally we add an
on_load hook that will include this module in
Put all this together and you should see stuff like
Completed 200 OK in 17ms (Views: 10.8ms | ActiveRecord: 0.3ms | Solr: 3.7ms)
in your logs.
 At the time of writing rails 3.0.7 actually does this incorrectly because it doesn’t consider time after rendering, or when no view was rendered at all