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
...(略)...