instrument elastic searchable queries

lib/elastic_searchable/log_instrumentation.rb

@@ -0,0 +1,37 @@
+module ElasticSearchable
+  class LogSubscriber < ActiveSupport::LogSubscriber
+    def query(event)
+      return unless logger.debug?
+
+      name = '%s (%.1fms)' % ["ElasticSearchable Query", event.duration]
+
+      params = event.payload[:query].merge event.payload[:options]
+      # produces: 'query: "foo" OR "bar", rows: 3, ...'
+      options = params.map{ |k, v| "#{k}: #{color(v, BOLD, true)}" }.join(', ')
+
+      debug "  #{color(name, YELLOW, true)}  [ #{query} ]"
+    end
+  end
+
+  module ControllerRuntime
+    extend ActiveSupport::Concern
+
+    protected
+    def append_info_to_payload(payload)
+      super
+      payload[:elastic_searchable_runtime] = ElasticSearchable::LogSubscriber.runtime
+    end
+
+    module ClassMethods
+      def log_process_action(payload)
+        messages, elastic_searchable_runtime = super, payload[:elastic_searchable_runtime]
+        messages << ("ElasticSearchable: %.1fms" % elastic_searchable_runtime.to_f) if elastic_searchable_runtime
+        messages
+      end
+    end
+  end
+end
+ElasticSearchable::LogSubscriber.attach_to :elastic_searchable
+ActiveSupport.on_load(:action_controller) do
+  include ElasticSearchable::ControllerRuntime
+end

lib/elastic_searchable/queries.rb

@@ -35,16 +35,18 @@ def search(query, options = {})
         query[:sort] = sort
       end
 
-      response = ElasticSearchable.request :get, index_mapping_path('_search'), :query => query, :json_body => options
-      hits = response['hits']
-      ids = hits['hits'].collect {|h| h['_id'].to_i }
-      results = self.find(ids).sort_by {|result| ids.index(result.id) }
+      ActiveSupport::Notifications.instrument("query.elastic_searchable", :query => query, :options => options) do
+        response = ElasticSearchable.request :get, index_mapping_path('_search'), :query => query, :json_body => options
+        hits = response['hits']
+        ids = hits['hits'].collect {|h| h['_id'].to_i }
+        results = self.find(ids).sort_by {|result| ids.index(result.id) }
 
-      results.each do |result|
-        result.instance_variable_set '@hit', hits['hits'][ids.index(result.id)]
-      end
+        results.each do |result|
+          result.instance_variable_set '@hit', hits['hits'][ids.index(result.id)]
+        end
 
-      ElasticSearchable::Paginator.handler.new(results, page, options[:size], hits['total'])
+        return ElasticSearchable::Paginator.handler.new(results, page, options[:size], hits['total'])
+      end
     end
 
     private