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

ActiveSupport::Notifications.instrument('some_task.my_app', data) do
  #do some processing
end

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

module Solr
  class Connection
    def send_with_instrumentation(request)
      ActiveSupport::Notifications.instrument("send_query.solr") do
        send_without_instrumentation(request)
      end
    end
    alias_method_chain :send, :instrumentation
  end
end

Here 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

module Solr
  class LogSubscriber < ActiveSupport::LogSubscriber
    def self.runtime=(value)
      Thread.current["solr_runtime"] = value
    end

    def self.runtime
      Thread.current["solr_runtime"] ||= 0
    end

    def self.reset_runtime
      rt, self.runtime = runtime, 0
      rt
    end

    def send_query(event)
      self.class.runtime += event.duration
    end
  end
end

Solr::LogSubscriber.attach_to :solr

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 runtime and runtime= method. 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]:

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

module Solr
  module Railties
    module ControllerRuntime
      extend ActiveSupport::Concern

    protected

      attr_internal :solr_runtime_before_render
      attr_internal :solr_runtime_during_render

      def cleanup_view_runtime
        self.solr_runtime_before_render = Solr::LogSubscriber.reset_runtime
        runtime = super
        self.solr_runtime_during_render = Solr::LogSubscriber.reset_runtime
        runtime - solr_runtime_during_render
      end

      def append_info_to_payload(payload)
        super
        payload[:solr_runtime] = (solr_runtime_before_render || 0) +
                                 (solr_runtime_during_render || 0) +
                                 Solr::LogSubscriber.reset_runtime
      end

      module ClassMethods
        def log_process_action(payload)
          messages, solr_runtime = super, payload[:solr_runtime]
          messages << ("Solr: %.1fms" % solr_runtime) if solr_runtime
          messages
        end
      end
    end
  end
end
ActiveSupport.on_load(:action_controller) do
   include Solr::Railties::ControllerRuntime
end

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 ActionController::Base.

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.

[1] 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