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)

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:

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:

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.

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:

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.

This comment has been minimized.

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.

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.

This comment has been minimized.

This comment has been minimized.

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?

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?