ActiveRecord: Is it possible to get the number of DB queries executed in addition to total time in the Rails log?

Question

For every request, I get this in the logs:

Completed 200 OK in 854ms (Views: 1.0ms | ActiveRecord: 17.0ms)

Is it possible to get it to also include the number of queries?
Something like:

Completed 200 OK in 854ms (Views: 1.0ms | ActiveRecord: 17.0ms | Queries: 10)

Ideally, I'd like all the "cached" ones to show up in that count too. Ie, even if the "cache" is saving me from "N+1" queries from hitting the DB, I still want to know I have a problem.

I'm fine with monkeypatching / manually editing something, since I really want this just for my dev box.

(If this can be made civilizedly so I can have it in production, that's even better, but if not, I'm fine with just having a manually modified Rails in my own machine)

Thanks!
Daniel

Answer 1

I know the ThinkingSphinx gem does something quite like this, adding the time spent running Sphinx queries to the summary in the log. You can probably do something similar ( maybe by making your own gem, since I bet other people would appreciate this functionality) to make the number of queries appear. I haven't really looked hard at how it works, but it looks like modifications to ActionController and LogSubscriber are responsible:

lib/thinking_sphinx/action_controller.rb:

module ThinkingSphinx
  module ActionController
    extend ActiveSupport::Concern

    protected

    attr_internal :query_runtime

    def cleanup_view_runtime
      log_subscriber = ThinkingSphinx::ActiveRecord::LogSubscriber
      query_runtime_pre_render = log_subscriber.reset_runtime
      runtime = super
      query_runtime_post_render = log_subscriber.reset_runtime
      self.query_runtime = query_runtime_pre_render + query_runtime_post_render
      runtime - query_runtime_post_render
    end

    def append_info_to_payload(payload)
      super
      payload[:query_runtime] = query_runtime
    end

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

lib/thinking_sphinx/active_record/log_subscriber.rb:

require 'active_support/log_subscriber'

module ThinkingSphinx
  module ActiveRecord
    class LogSubscriber < ActiveSupport::LogSubscriber
      def self.runtime=(value)
        Thread.current['thinking_sphinx_query_runtime'] = value
      end

      def self.runtime
        Thread.current['thinking_sphinx_query_runtime'] ||= 0
      end

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

      def initialize
        super
        @odd_or_even = false
      end

      def query(event)
        self.class.runtime += event.duration
        return unless logger.debug?

        identifier = color('Sphinx Query (%.1fms)' % event.duration, GREEN, true)
        query = event.payload[:query]
        query = color query, nil, true if odd?

        debug "  #{identifier}  #{query}"
      end

      def message(event)
        return unless logger.debug?

        identifier = color 'Sphinx', GREEN, true
        message = event.payload[:message]
        message = color message, nil, true if odd?

        debug "  #{identifier}  #{message}"
      end

      def odd?
        @odd_or_even = !@odd_or_even
      end

      def logger
        return @logger if defined? @logger
        self.logger = ::ActiveRecord::Base.logger
      end

      def logger=(logger)
        @logger = logger
      end

      attach_to :thinking_sphinx
    end
  end
end

I hope this helps.