bhornseth · February 25, 2016 20:43 · Oct 6, 2010 · Sep 9, 2010 · Sep 9, 2010 · Sep 9, 2010
diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -102,4 +102,7 @@ Notice that we no longer have to jump through the `self.included` hoops anymore;
 
 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](http://github.com/rails/rails/blob/master/activerecord/lib/active_record/log_subscriber.rb) 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](http://www.igvita.com/2010/07/19/speed-tracer-server-side-tracing-with-rack/) by subscribing to timing events and outputting them to Google Chrome's [Speed Tracer](http://code.google.com/webtoolkit/speedtracer/) browser extension.  I imagine notifications will simplify NewRelic's monitoring gem as well.
+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](http://www.igvita.com/2010/07/19/speed-tracer-server-side-tracing-with-rack/) by subscribing to timing events and outputting them to Google Chrome's [Speed Tracer](http://code.google.com/webtoolkit/speedtracer/) browser extension.  I imagine notifications will simplify NewRelic's monitoring gem as well.
+
+
+Thanks to Bryan Helmkamp ([@brynary](http://twitter.com/brynary)) for technical proofreading.
diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -49,11 +49,11 @@ I've wrapped my client call in an ActiveSupport::Notifications block with the fi
 
 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:
+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 Solr deletes and commits by wrapping the Solr calls with "delete.delsolr" and "commit.delsolr" and adding the appropriate methods.
+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:
 

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -24,8 +24,7 @@ ActiveRecord provides an excellent example of how to subscribe to notifications.
     class SolrDocument
       def self.query(query_type, options={})
         ActiveSupport::Notifications.instrument("query.delsolr",
-                                                :options => options,
-                                                :query_type => query_type) do
+                                                :query => options) do
           ProductDocument.delsolr_client.query(query_type, options)
         end
       end
@@ -41,7 +40,7 @@ I've wrapped my client call in an ActiveSupport::Notifications block with the fi
           name = '%s (%.1fms)' % ["SOLR Query", event.duration]
 
           # produces: 'query: "foo" OR "bar", rows: 3, ...'
-          query = event.payload[:options].map{ |k, v| "#{k}: #{color(v, BOLD, true)}" }.join(', ')
+          query = event.payload[:query].map{ |k, v| "#{k}: #{color(v, BOLD, true)}" }.join(', ')
 
           debug "  #{color(name, YELLOW, true)}  [ #{query} ]"
         end

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -38,7 +38,7 @@ I've wrapped my client call in an ActiveSupport::Notifications block with the fi
         def query(event)
           return unless logger.debug?
 
-          name = '%s (%.1fms)' % [event.payload[:name], event.duration]
+          name = '%s (%.1fms)' % ["SOLR Query", event.duration]
 
           # produces: 'query: "foo" OR "bar", rows: 3, ...'
           query = event.payload[:options].map{ |k, v| "#{k}: #{color(v, BOLD, true)}" }.join(', ')

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -22,12 +22,11 @@ In Rails 3, logging has been abstracted into [ActiveSupport::Notifications](http
 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(handler, options={})
+      def self.query(query_type, options={})
         ActiveSupport::Notifications.instrument("query.delsolr",
                                                 :options => options,
-                                                :handler => handler,
-                                                :name => "SOLR Query") do
-          ProductDocument.delsolr_client.query(handler, options)
+                                                :query_type => query_type) do
+          ProductDocument.delsolr_client.query(query_type, options)
         end
       end
     end

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -1,7 +1,7 @@
 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:
+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

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -1,7 +1,7 @@
 Instrument Anything in Rails 3
 ==============================
 
-I've started a few Rails 3.0 apps since it was released a week ago 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:
+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:
 
     Started GET "/" for 127.0.0.1 at Mon Sep 06 01:07:11 -0400 2010
       Processing by HomeController#index as HTML

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -13,9 +13,9 @@ I've started a few Rails 3.0 apps since it was released a week ago and I'm const
     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?
+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](http://delsolr.rubyforge.org/) 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.
+The app I'm working on at Market.io uses Solr extensively via the [delsolr](http://delsolr.rubyforge.org/) 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](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/Notifications), which publishes logging events, and [ActiveSupport::LogSubscriber](http://rdoc.info/github/rails/rails/v3.0.0/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.)
 
@@ -55,9 +55,9 @@ Next, we need to register our subscriber to receive events:
 
     SolrInstrumentation::LogSubscriber.attach_to :delsolr
 
-The next step would be to instrument our solr deletes and commits by wrapping the solr calls with "delete.delsolr" and "commit.delsolr" and adding the appropriate methods.
+The next step would be to instrument our Solr deletes and commits 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:
+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
@@ -70,7 +70,7 @@ Now we should have something like this in our rails log:
     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.
+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

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -17,7 +17,7 @@ This output format is very informative, but what if we're using mongodb or couch
 
 The app I'm working on at Market.io uses Solr extensively via the [delsolr](http://delsolr.rubyforge.org/) 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](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/Notifications), which publish logging events, and [ActiveSupport::LogSubscriber](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/LogSubscriber), which consume the events and log 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)
+In Rails 3, logging has been abstracted into [ActiveSupport::Notifications](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/Notifications), which publishes logging events, and [ActiveSupport::LogSubscriber](http://rdoc.info/github/rails/rails/v3.0.0/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:
 

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -1,7 +1,7 @@
 Instrument Anything in Rails 3
 ==============================
 
-I've started a few Rails 3.0 apps since it was released a week ago, 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, actionview, etc.  By default Rails 3 logs look slightly spiffier than those produced by Rails 2.3:
+I've started a few Rails 3.0 apps since it was released a week ago 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:
 
     Started GET "/" for 127.0.0.1 at Mon Sep 06 01:07:11 -0400 2010
       Processing by HomeController#index as HTML

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -1,5 +1,5 @@
 Instrument Anything in Rails 3
-========================================
+==============================
 
 I've started a few Rails 3.0 apps since it was released a week ago, 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, actionview, etc.  By default Rails 3 logs look slightly spiffier than those produced by Rails 2.3:
 

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -1,4 +1,4 @@
-Instrumenting Custom Services in Rails 3
+Instrument Anything in Rails 3
 ========================================
 
 I've started a few Rails 3.0 apps since it was released a week ago, 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, actionview, etc.  By default Rails 3 logs look slightly spiffier than those produced by Rails 2.3:

diff --git a/Instrument Anything in Rails 3.md b/Instrument Anything in Rails 3.md
@@ -1,7 +1,7 @@
-Instrument Anything in Rails 3
+Instrumenting Custom Services in Rails 3
 ========================================
 
-With Rails 3.0 recently released, 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, actionview, etc:
+I've started a few Rails 3.0 apps since it was released a week ago, 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, actionview, etc.  By default Rails 3 logs look slightly spiffier than those produced by Rails 2.3:
 
     Started GET "/" for 127.0.0.1 at Mon Sep 06 01:07:11 -0400 2010
       Processing by HomeController#index as HTML

diff --git a/Rails 3 Instrumentation.md → Instrument Anything in Rails 3.md b/Rails 3 Instrumentation.md → Instrument Anything in Rails 3.md
@@ -1,4 +1,4 @@
-Instrumenting Custom Services in Rails 3
+Instrument Anything in Rails 3
 ========================================
 
 With Rails 3.0 recently released, 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, actionview, etc:
@@ -15,11 +15,11 @@ With Rails 3.0 recently released, I'm constantly finding useful new improvements
 
 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](http://delsolr.rubyforge.org/) 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.
+The app I'm working on at Market.io uses Solr extensively via the [delsolr](http://delsolr.rubyforge.org/) 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](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/Notifications), which publish logging events, and [ActiveSupport::LogSubscriber](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/LogSubscriber), which consume the events and log the output.  This abstraction lets any number of entities publish notifications.
+In Rails 3, logging has been abstracted into [ActiveSupport::Notifications](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/Notifications), which publish logging events, and [ActiveSupport::LogSubscriber](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/LogSubscriber), which consume the events and log 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.
+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(handler, options={})

diff --git a/Rails 3 Instrumentation.md b/Rails 3 Instrumentation.md
@@ -15,11 +15,11 @@ With Rails 3.0 recently released, I'm constantly finding useful new improvements
 
 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.  I could just add `Rails.logger.info "Solr query: #{query}"` but now Rails provides a better way.
+The app I'm working on at Market.io uses Solr extensively via the [delsolr](http://delsolr.rubyforge.org/) 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 publish logging events, and ActiveSupport::LogSubscriber, which consume the events and log the output.  This abstraction lets any number of entities subscribe to the notifications.
+In Rails 3, logging has been abstracted into [ActiveSupport::Notifications](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/Notifications), which publish logging events, and [ActiveSupport::LogSubscriber](http://rdoc.info/github/rails/rails/v3.0.0/ActiveSupport/LogSubscriber), which consume the events and log the output.  This abstraction lets any number of entities publish notifications.
 
-ActiveRecord provides an excellent example of how to subscribe to notifications.  I've adapted it to solr with minimal changes:
+ActiveRecord provides an excellent example of how to subscribe to notifications.  I've adapted it to delsolr with minimal changes.
 
     class SolrDocument
       def self.query(handler, options={})
@@ -32,7 +32,7 @@ ActiveRecord provides an excellent example of how to subscribe to notifications.
       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:
+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
@@ -49,13 +49,13 @@ I've wrapped my client call in an ActiveSupport::Notifications block with the fi
       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.
+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:
 
     SolrInstrumentation::LogSubscriber.attach_to :delsolr
 
-The next step would be to instrument our solr deletes and commits by wrapping the solr calls with "*.delsolr" and adding the appropriate methods.
+The next step would be to instrument our solr deletes and commits 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:
 
@@ -98,10 +98,10 @@ Now it's easy to spot and debug the solr queries, but it would be nice to see th
     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:
+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)
+    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 ActionController to return the real view rendering time.  It involves a bit more work in calculating the service's runtime; check out ActiveRecord::LogSubscriber for an example.
+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](http://github.com/rails/rails/blob/master/activerecord/lib/active_record/log_subscriber.rb) 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)[http://www.igvita.com/2010/07/19/speed-tracer-server-side-tracing-with-rack/] by subscribing to timing events and outputting them to Google Chrome's Speed Tracer browser extension.  I imagine notifications will also vastly simplify NewRelic's monitoring gem as well.
+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](http://www.igvita.com/2010/07/19/speed-tracer-server-side-tracing-with-rack/) by subscribing to timing events and outputting them to Google Chrome's [Speed Tracer](http://code.google.com/webtoolkit/speedtracer/) browser extension.  I imagine notifications will simplify NewRelic's monitoring gem as well.
diff --git a/Rails 3 Instrumentation.md b/Rails 3 Instrumentation.md
@@ -0,0 +1,107 @@
+Instrumenting Custom Services in Rails 3
+========================================
+
+With Rails 3.0 recently released, 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, actionview, etc:
+
+    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.  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 publish logging events, and ActiveSupport::LogSubscriber, which consume the events and log the output.  This abstraction lets any number of entities subscribe to the notifications.
+
+ActiveRecord provides an excellent example of how to subscribe to notifications.  I've adapted it to solr with minimal changes:
+
+    class SolrDocument
+      def self.query(handler, options={})
+        ActiveSupport::Notifications.instrument("query.delsolr",
+                                                :options => options,
+                                                :handler => handler,
+                                                :name => "SOLR Query") do
+          ProductDocument.delsolr_client.query(handler, 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)' % [event.payload[:name], event.duration]
+
+          # produces: 'query: "foo" OR "bar", rows: 3, ...'
+          query = event.payload[:options].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:
+
+    SolrInstrumentation::LogSubscriber.attach_to :delsolr
+
+The next step would be to instrument our solr deletes and commits by wrapping the solr calls with "*.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 ActionController to return the real view rendering time.  It involves a bit more work in calculating the service's runtime; check out 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)[http://www.igvita.com/2010/07/19/speed-tracer-server-side-tracing-with-rack/] by subscribing to timing events and outputting them to Google Chrome's Speed Tracer browser extension.  I imagine notifications will also vastly simplify NewRelic's monitoring gem as well.
No results found