How to use Rails 3.0's new notification system to inject custom log events

Instrument Anything in Rails 3.md

Instrument Anything in Rails 3

With Rails 3.0 released a few weeks ago I've migrated a few apps and I'm constantly finding useful new improvements. One such improvement is the ability to log anything in the same way that Rails internally logs ActiveRecord and ActionView. By default Rails 3 logs look slightly spiffier than those produced by Rails 2.3: (notice the second line has been cleaned up)

Started GET "/" for 127.0.0.1 at Mon Sep 06 01:07:11 -0400 2010
  Processing by HomeController#index as HTML
  User Load (0.2ms)  SELECT `users`.* FROM `users` WHERE (`users`.`id` = 3) LIMIT 1
  CACHE (0.0ms)  SELECT `users`.* FROM `users` WHERE (`users`.`id` = 3) LIMIT 1
Rendered layouts/_nav.html.erb (363.4ms)
Rendered layouts/_nav.html.erb (1.1ms)
Rendered layouts/_footer.html.erb (2.6ms)
Rendered home/index.html.erb within layouts/application (503.6ms)
Completed 200 OK in 510ms (Views: 507.9ms | ActiveRecord: 406.3ms)

This output format is very informative, but what if we're using MongoDB or CouchDB instead of ActiveRecord? What if our page has a Solr query that takes up a signification portion of the response time, and we want to break it out of the total?

The app I'm working on at Market.io uses Solr extensively via the delsolr gem. Since delsolr is not Rails-specific, I have created a wrapper around the service calls to add hooks. If I wanted to log Solr queries I could just add Rails.logger.info "Solr query: #{query}" but now Rails provides a better way.

In Rails 3, logging has been abstracted into ActiveSupport::Notifications, which publishes logging events, and ActiveSupport::LogSubscriber, which consumes the events and logs the output. This abstraction lets any number of entities publish notifications. (I'm calling those entities "services" for the purpose of this article, but any call can be instrumented.)

ActiveRecord provides an excellent example of how to subscribe to notifications. I've adapted it to delsolr with minimal changes. First we tell Rails what to instrument:

class SolrDocument
  def self.query(query_type, options={})
    ActiveSupport::Notifications.instrument("query.delsolr",
                                            :query => options) do
      ProductDocument.delsolr_client.query(query_type, options)
    end
  end
end

I've wrapped my client call in an ActiveSupport::Notifications block with the first argument in the format {action}.{service}. The second argument is the "payload", a hash that gets passed to the log subscriber. In order to catch the notification, we need to write a subscriber:

module SolrInstrumentation
  class LogSubscriber < ActiveSupport::LogSubscriber
    def query(event)
      return unless logger.debug?

      name = '%s (%.1fms)' % ["SOLR Query", event.duration]

      # produces: 'query: "foo" OR "bar", rows: 3, ...'
      query = event.payload[:query].map{ |k, v| "#{k}: #{color(v, BOLD, true)}" }.join(', ')

      debug "  #{color(name, YELLOW, true)}  [ #{query} ]"
    end
  end
end

The subscriber will receive an event with a method #payload that returns the hash we passed in earlier with the :duration key added. We simply construct a log line and then use #debug to output it to our logfile. ActiveSupport::LogSubscriber comes with a #color method that makes highlighting output very easy.

Next, we need to register our subscriber to receive events. We attach our LogSubscriber to all events in the delsolr namespace:

SolrInstrumentation::LogSubscriber.attach_to :delsolr

The next step would be to instrument our other Solr calls such as delete and commit by wrapping the Solr calls with "delete.delsolr" and "commit.delsolr" and adding the appropriate methods.

Now we should have something like this in our Rails log:

Started GET "/" for 127.0.0.1 at Mon Sep 06 01:07:11 -0400 2010
  Processing by HomeController#index as HTML
  User Load (0.2ms)  SELECT `users`.* FROM `users` WHERE (`users`.`id` = 3) LIMIT 1
  CACHE (0.0ms)  SELECT `users`.* FROM `users` WHERE (`users`.`id` = 3) LIMIT 1
  SOLR Query (52.2ms)  [ rows: 25, query: "rails 3" OR "rails 2.3", start: 0, fields: * score, sort: created_at desc ]
Rendered layouts/_nav.html.erb (363.4ms)
Rendered layouts/_nav.html.erb (1.1ms)
Rendered layouts/_footer.html.erb (2.6ms)
Rendered home/index.html.erb within layouts/application (503.6ms)
Completed 200 OK in 562ms (Views: 507.9ms | ActiveRecord: 406.3ms)

Now it's easy to spot and debug the Solr queries, but it would be nice to see the breakout as well. For that we need to extend our controllers.

module SolrInstrumentation
  module ControllerRuntime
    extend ActiveSupport::Concern

    protected

    def append_info_to_payload(payload)
      super
      payload[:solr_runtime] = SolrInstrumentation::LogSubscriber.runtime
    end

    module ClassMethods
      def log_process_action(payload)
        messages, solr_runtime = super, payload[:solr_runtime]
        messages << ("Solr: %.1fms" % solr_runtime.to_f) if solr_runtime
        messages
      end
    end
  end
end

ActiveSupport.on_load(:action_controller) do
  include SolrInstrumentation::ControllerRuntime
end

Notice that we no longer have to jump through the self.included hoops anymore; in Rails 3 we can extend ActiveSupport::Concern to easily add features to ActionController. ActionController has instrumented the entire request in the same way that we instrumented our Solr call, so we just need to call our controller's #append_info_to_payload hook to inject our runtime info into the request notification event. Lastly, we use the #log_process_action hook to catch the payload we just modified and generate a message, which should appear in the logs:

Completed 200 OK in 562ms (Views: 507.9ms | ActiveRecord: 406.3ms | Solr: 52.2ms)

Solr normally shouldn't be called in the views, but if your service is used frequently in views and you don't want it to count towards the view's rendering time you can add a #cleanup_view_runtime method to the ControllerRuntime module to return the real view rendering time. It involves a bit more work in calculating the service's runtime; check out the source of ActiveRecord::LogSubscriber for an example.

Rails 3's notifications open up a lot of possibilities for both publishing and subscribing to events. Already Ilya Grigorik has taken advantage of this in his Speed Tracer Rack middleware by subscribing to timing events and outputting them to Google Chrome's Speed Tracer browser extension. I imagine notifications will simplify NewRelic's monitoring gem as well.

Thanks to Bryan Helmkamp (@brynary) for technical proofreading.

Thanx for sharing.

Thanks :)

Looks like a huge overhead. What do you think about logging to a database table with defined columns? -- Stephan

I haven't noticed much overhead in the requests after adding it, but I'd be interested to profile it and see exactly how much it adds. For the value it provides, I think it's worth it. If you're running a massive high-traffic site you can choose not to include notifications in your controllers, but for the average rails site it's pretty useful.

You could log to a database table, but a db write per request would be a pretty large overhead. You'd want to make sure you had minimal indexes on that table. For writing logfiles to a db you might want to look into something like MongoDB which sacrifices some consistency for very high write throughput.

Thanks for the info! I'm a little puzzled about something, though. Where would you place your attach_to call?

I usually just put it after the SolrInstrumentation definition, but you can put it where ever you want as long as it gets run when Rails is loaded.

Very helpful. Thanks!

Made my day! But I'm still wondering about one thing:
How did you implement SolrInstrumentation::LogSubscriber.runtime
It's a class method. Accumulating runtime in a class variable will break on concurrent access.
ActiveSupport::LogSubscriber solves this with using Thread.current - which doesn't feel completely right to me. Were you able to collect this data in a different, clean request scoped object?