ActiveRecord::Base.connection.execute にかかった時間という事でよさそう。mysql2 の場合、Mysql2::Client#query にかかった時間。

調査メモ

payload[:db_runtime] に入っている実行時間を書いている模様。

activerecord-3.2.13/lib/active_record/railties/controller_runtime.rb

module ActiveRecord
  module Railties
    module ControllerRuntime #:nodoc:
      extend ActiveSupport::Concern

    protected

      attr_internal :db_runtime
      
      ...(略)...
      
      def append_info_to_payload(payload)
        super
        if ActiveRecord::Base.connected?
          payload[:db_runtime] = (db_runtime || 0) + ActiveRecord::LogSubscriber.reset_runtime
        end
      end
      
      module ClassMethods
        def log_process_action(payload)
          messages, db_runtime = super, payload[:db_runtime]
          messages << ("ActiveRecord: %.1fms" % db_runtime.to_f) if db_runtime
          messages
        end
      end
    end
  end
end

payload は process_action に渡された event から取り出せる模様。event は ActiveSupport::Notifications::Event のインスタンス。

actionpack-3.2.13/lib/action_controller/log_subscriber.rb

module ActionController
  class LogSubscriber < ActiveSupport::LogSubscriber
  
  ...(略)...
  
    def process_action(event)
      payload   = event.payload
      additions = ActionController::Base.log_process_action(payload)

      status = payload[:status]
      if status.nil? && payload[:exception].present?
        exception_class_name = payload[:exception].first
        status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
      end
      message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in %.0fms" % event.duration
      message << " (#{additions.join(" | ")})" unless additions.blank?

      info(message)
    end
      
    ...(略)...

ActionController::LogSubscriber.attach_to :action_controller

actionpack-3.2.13/lib/action_controller/metal/instrumentation.rb

module ActionController
  # Adds instrumentation to several ends in ActionController::Base. It also provides
  # some hooks related with process_action, this allows an ORM like Active Record
  # and/or DataMapper to plug in ActionController and show related information.
  #
  # Check ActiveRecord::Railties::ControllerRuntime for an example.
  module Instrumentation
    extend ActiveSupport::Concern

    include AbstractController::Logger

    attr_internal :view_runtime

    def process_action(*args)
      raw_payload = {
        :controller => self.class.name,
        :action     => self.action_name,
        :params     => request.filtered_parameters,
        :format     => request.format.try(:ref),
        :method     => request.method,
        :path       => (request.fullpath rescue "unknown")
      }

      ActiveSupport::Notifications.instrument("start_processing.action_controller", raw_payload.dup)

      ActiveSupport::Notifications.instrument("process_action.action_controller", raw_payload) do |payload|
        result = super
        payload[:status] = response.status
        append_info_to_payload(payload)
        result
      end
    end

    ...(略)...

さて、db_runtime にはどんな値が入るのか。render 前後に ActiveRecord::LogSubscriber に溜め込まれた時間？

activerecord-3.2.13/lib/active_record/railties/controller_runtime.rb

module ActiveRecord
  module Railties
    module ControllerRuntime #:nodoc:
      extend ActiveSupport::Concern

    protected

      attr_internal :db_runtime
      
      ...(略)...
      
      def cleanup_view_runtime
        if ActiveRecord::Base.connected?
          db_rt_before_render = ActiveRecord::LogSubscriber.reset_runtime
          runtime = super
          db_rt_after_render = ActiveRecord::LogSubscriber.reset_runtime
          self.db_runtime = db_rt_before_render + db_rt_after_render
          runtime - db_rt_after_render
        else
          super
        end
      end

sql.active_record のタイミングで加算されていく模様。

activerecord-3.2.13/lib/active_record/log_subscriber.rb

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

    def self.runtime
      Thread.current["active_record_sql_runtime"] ||= 0
    end

    def self.reset_runtime
      rt, self.runtime = runtime, 0
      rt
    end
    
    ...(略)...

    def sql(event)
      self.class.runtime += event.duration
    
    ...(略)...

cache_sql と log が関係していそう。

activerecord-3.2.13/lib/active_record/connection_adapters/abstract/query_cache.rb

module ActiveRecord
  module ConnectionAdapters # :nodoc:
    module QueryCache
    
    ...(略)...
    
      private
        def cache_sql(sql, binds)
          result =
            if @query_cache[sql].key?(binds)
              ActiveSupport::Notifications.instrument("sql.active_record",
                :sql => sql, :binds => binds, :name => "CACHE", :connection_id => object_id)
              @query_cache[sql][binds]
            else
              @query_cache[sql][binds] = yield
            end

          result.collect { |row| row.dup }
        end

        def locked?(arel)
          if arel.respond_to?(:locked)
            arel.locked
          else
            false
          end
        end
    end
  end
end

connection.execute の実行時間が対象となっている模様。

activerecord-3.2.13/lib/active_record/connection_adapters/abstract_adapter.rb

module ActiveRecord
  module ConnectionAdapters # :nodoc:
  
  ...(略)...
  
      protected

        def log(sql, name = "SQL", binds = [])
          @instrumenter.instrument(
            "sql.active_record",
            :sql           => sql,
            :name          => name,
            :connection_id => object_id,
            :binds         => binds) { yield }
        rescue Exception => e
          message = "#{e.class.name}: #{e.message}: #{sql}"
          @logger.debug message if @logger
          exception = translate_exception(e, message)
          exception.set_backtrace e.backtrace
          raise exception
        end
        
...(略)...

activerecord-3.2.13/lib/active_record/connection_adapters/abstract_mysql_adapter.rb

module ActiveRecord
  module ConnectionAdapters
    class AbstractMysqlAdapter < AbstractAdapter
    
    ...(略)...
    
      # Executes the SQL statement in the context of this connection.
      def execute(sql, name = nil)
        if name == :skip_logging
          @connection.query(sql)
        else
          log(sql, name) { @connection.query(sql) }
        end
      rescue ActiveRecord::StatementInvalid => exception
        if exception.message.split(":").first =~ /Packets out of order/
          raise ActiveRecord::StatementInvalid, "'Packets out of order' error was received from the database. Please update your mysql bindings (gem install mysql) and read http://dev.mysql.com/doc/mysql/en/password-hashing.html for more information. If you're on Windows, use the Instant Rails installer to get the updated mysql bindings."
        else
          raise
        end
      end
    
    ...(略)...

activerecord-3.2.13/lib/active_record/connection_adapters/mysql2_adapter.rb

module ActiveRecord
  ...(略)...

  module ConnectionAdapters
    class Mysql2Adapter < AbstractMysqlAdapter

      def exec_query(sql, name = 'SQL', binds = [])
        result = execute(sql, name)
        ActiveRecord::Result.new(result.fields, result.to_a)
      end

  ...(略)...