kotovalexarian-likes-github/rails--rails
1
0
Fork 0
mirror of https://github.com/rails/rails.git synced 2022-11-09 12:12:34 -05:00
Code Releases Activity

implements automatic EXPLAIN logging for slow queries

Browse source
This commit is contained in:
Xavier Noria 2011-12-02 04:32:18 -08:00
parent 4d20de8a50
commit 0306f82e0c
18 changed files with 355 additions and 97 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

11
activerecord/CHANGELOG.md
View file

@ -1,5 +1,16 @@
## Rails 3.2.0 (unreleased) ##
* Implements automatic EXPLAIN logging for slow queries.
A new configuration parameter `config.active_record.auto_explain_threshold_in_seconds`
determines what's to be considered a slow query. Setting that to `nil` disables
this feature. Defaults are 0.5 in development mode, and `nil` in test and production
modes.
As of this writing there's support for SQLite, MySQL (mysql2 adapter), and
PostgreSQL.
*fxn*
* Implemented ActiveRecord::Relation#pluck method

2
activerecord/lib/active_record.rb
View file

@ -50,6 +50,7 @@ module ActiveRecord
autoload :PredicateBuilder
autoload :SpawnMethods
autoload :Batches
autoload :Explain
end
autoload :Base
@ -75,6 +76,7 @@ module ActiveRecord
autoload :Transactions
autoload :Validations
autoload :IdentityMap
autoload :Explain
end
module Coders

10
activerecord/lib/active_record/base.rb
View file

@ -433,6 +433,11 @@ module ActiveRecord #:nodoc:
class_attribute :default_scopes, :instance_writer => false
self.default_scopes = []
# If a query takes longer than these many seconds we log its query plan
# automatically. nil disables this feature.
class_attribute :auto_explain_threshold_in_seconds, :instance_writer => false
self.auto_explain_threshold_in_seconds = nil
class_attribute :_attr_readonly, :instance_writer => false
self._attr_readonly = []
@ -484,7 +489,9 @@ module ActiveRecord #:nodoc:
# Post.find_by_sql ["SELECT title FROM posts WHERE author = ? AND created > ?", author_id, start_date]
# > [#<Post:0x36bff9c @attributes={"title"=>"The Cheap Man Buys Twice"}>, ...]
def find_by_sql(sql, binds = [])
connection.select_all(sanitize_sql(sql), "#{name} Load", binds).collect! { |record| instantiate(record) }
logging_query_plan do
connection.select_all(sanitize_sql(sql), "#{name} Load", binds).collect! { |record| instantiate(record) }
end
end
# Creates an object (or multiple objects) and saves it to the database, if validations pass.
@ -2206,6 +2213,7 @@ MSG
include Associations, NamedScope
include IdentityMap
include ActiveModel::SecurePassword
extend Explain
# AutosaveAssociation needs to be included before Transactions, because we want
# #save_with_autosave_associations to be wrapped inside a transaction.

6
activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
View file

@ -142,6 +142,12 @@ module ActiveRecord
false
end
# Does this adapter support explain? As of this writing sqlite3,
# mysql2, and postgresql are the only ones that do.
def supports_explain?
false
end
# QUOTING ==================================================
# Override to return the quoted table name. Defaults to column quoting.

74
activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb
View file

@ -225,80 +225,6 @@ module ActiveRecord
# DATABASE STATEMENTS ======================================
def explain(arel)
sql = "EXPLAIN #{to_sql(arel)}"
start = Time.now
result = exec_query(sql, 'EXPLAIN')
elapsed = Time.now - start
ExplainPrettyPrinter.new.pp(result, elapsed)
end
class ExplainPrettyPrinter # :nodoc:
# Pretty prints the result of a EXPLAIN in a way that resembles the output of the
# MySQL shell:
#
# +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
# | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
# +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
# | 1 | SIMPLE | users | const | PRIMARY | PRIMARY | 4 | const | 1 | |
# | 1 | SIMPLE | posts | ALL | NULL | NULL | NULL | NULL | 1 | Using where |
# +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
# 2 rows in set (0.00 sec)
#
# This is an exercise in Ruby hyperrealism :).
def pp(result, elapsed)
widths = compute_column_widths(result)
separator = build_separator(widths)
pp = []
pp << separator
pp << build_cells(result.columns, widths)
pp << separator
result.rows.each do |row|
pp << build_cells(row, widths)
end
pp << separator
pp << build_footer(result.rows.length, elapsed)
pp.join("\n") + "\n"
end
private
def compute_column_widths(result)
[].tap do |widths|
result.columns.each_with_index do |column, i|
cells_in_column = [column] + result.rows.map {|r| r[i].nil? ? 'NULL' : r[i].to_s}
widths << cells_in_column.map(&:length).max
end
end
end
def build_separator(widths)
padding = 1
'+' + widths.map {|w| '-' * (w + (padding*2))}.join('+') + '+'
end
def build_cells(items, widths)
cells = []
items.each_with_index do |item, i|
item = 'NULL' if item.nil?
justifier = item.is_a?(Numeric) ? 'rjust' : 'ljust'
cells << item.to_s.send(justifier, widths[i])
end
'| ' + cells.join(' | ') + ' |'
end
def build_footer(nrows, elapsed)
rows_label = nrows == 1 ? 'row' : 'rows'
"#{nrows} #{rows_label} in set (%.2f sec)" % elapsed
end
end
# Executes the SQL statement in the context of this connection.
def execute(sql, name = nil)
if name == :skip_logging

78
activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb
View file

@ -35,6 +35,10 @@ module ActiveRecord
configure_connection
end
def supports_explain?
true
end
# HELPER METHODS ===========================================
def each_hash(result) # :nodoc:
@ -93,6 +97,80 @@ module ActiveRecord
# DATABASE STATEMENTS ======================================
def explain(arel, binds = [])
sql = "EXPLAIN #{to_sql(arel)}"
start = Time.now
result = exec_query(sql, 'EXPLAIN', binds)
elapsed = Time.now - start
ExplainPrettyPrinter.new.pp(result, elapsed)
end
class ExplainPrettyPrinter # :nodoc:
# Pretty prints the result of a EXPLAIN in a way that resembles the output of the
# MySQL shell:
#
# +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
# | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
# +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
# | 1 | SIMPLE | users | const | PRIMARY | PRIMARY | 4 | const | 1 | |
# | 1 | SIMPLE | posts | ALL | NULL | NULL | NULL | NULL | 1 | Using where |
# +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
# 2 rows in set (0.00 sec)
#
# This is an exercise in Ruby hyperrealism :).
def pp(result, elapsed)
widths = compute_column_widths(result)
separator = build_separator(widths)
pp = []
pp << separator
pp << build_cells(result.columns, widths)
pp << separator
result.rows.each do |row|
pp << build_cells(row, widths)
end
pp << separator
pp << build_footer(result.rows.length, elapsed)
pp.join("\n") + "\n"
end
private
def compute_column_widths(result)
[].tap do |widths|
result.columns.each_with_index do |column, i|
cells_in_column = [column] + result.rows.map {|r| r[i].nil? ? 'NULL' : r[i].to_s}
widths << cells_in_column.map(&:length).max
end
end
end
def build_separator(widths)
padding = 1
'+' + widths.map {|w| '-' * (w + (padding*2))}.join('+') + '+'
end
def build_cells(items, widths)
cells = []
items.each_with_index do |item, i|
item = 'NULL' if item.nil?
justifier = item.is_a?(Numeric) ? 'rjust' : 'ljust'
cells << item.to_s.send(justifier, widths[i])
end
'| ' + cells.join(' | ') + ' |'
end
def build_footer(nrows, elapsed)
rows_label = nrows == 1 ? 'row' : 'rows'
"#{nrows} #{rows_label} in set (%.2f sec)" % elapsed
end
end
# FIXME: re-enable the following once a "better" query_cache solution is in core
#
# The overrides below perform much better than the originals in AbstractAdapter

9
activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
View file

@ -390,6 +390,11 @@ module ActiveRecord
true
end
# Returns true.
def supports_explain?
true
end
# Returns the configured supported identifier length supported by PostgreSQL
def table_alias_length
@table_alias_length ||= query('SHOW max_identifier_length')[0][0].to_i
@ -514,9 +519,9 @@ module ActiveRecord
# DATABASE STATEMENTS ======================================
def explain(arel)
def explain(arel, binds = [])
sql = "EXPLAIN #{to_sql(arel)}"
ExplainPrettyPrinter.new.pp(exec_query(sql))
ExplainPrettyPrinter.new.pp(exec_query(sql, 'EXPLAIN', binds))
end
class ExplainPrettyPrinter # :nodoc:

9
activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb
View file

@ -122,6 +122,11 @@ module ActiveRecord
true
end
# Returns true.
def supports_explain?
true
end
def requires_reloading?
true
end
@ -219,9 +224,9 @@ module ActiveRecord
# DATABASE STATEMENTS ======================================
def explain(arel)
def explain(arel, binds = [])
sql = "EXPLAIN QUERY PLAN #{to_sql(arel)}"
ExplainPrettyPrinter.new.pp(exec_query(sql, 'EXPLAIN'))
ExplainPrettyPrinter.new.pp(exec_query(sql, 'EXPLAIN', binds))
end
class ExplainPrettyPrinter

76
activerecord/lib/active_record/explain.rb Normal file
View file

@ -0,0 +1,76 @@
module ActiveRecord
module Explain # :nodoc
# logging_query_plan calls could appear nested in the call stack. In
# particular this happens when a relation fetches its records, since
# that results in find_by_sql calls downwards.
#
# This flag allows nested calls to detect this situation and bypass
# it, thus preventing repeated EXPLAINs.
LOGGING_QUERY_PLAN = :logging_query_plan
# If auto explain is enabled, this method triggers EXPLAIN logging for the
# queries triggered by the block if it takes more than the threshold as a
# whole. That is, the threshold is not checked against each individual
# query, but against the duration of the entire block. This approach is
# convenient for relations.
def logging_query_plan(&block)
if (t = auto_explain_threshold_in_seconds) && !Thread.current[LOGGING_QUERY_PLAN]
begin
Thread.current[LOGGING_QUERY_PLAN] = true
start = Time.now
result, sqls, binds = collecting_sqls_for_explain(&block)
logger.warn(exec_explain(sqls, binds)) if Time.now - start > t
result
ensure
Thread.current[LOGGING_QUERY_PLAN] = false
end
else
block.call
end
end
# SCHEMA queries cannot be EXPLAINed, also we do not want to run EXPLAIN on
# our own EXPLAINs now matter how loopingly beautiful that would be.
SKIP_EXPLAIN_FOR = %(SCHEMA EXPLAIN)
def ignore_explain_notification?(payload)
payload[:exception] || SKIP_EXPLAIN_FOR.include?(payload[:name])
end
# Collects all queries executed while the passed block runs. Returns an
# array with three elements, the result of the block, the strings with the
# queries, and their respective bindings.
def collecting_sqls_for_explain(&block)
sqls = []
binds = []
callback = lambda do |*args|
payload = args.last
unless ignore_explain_notification?(payload)
sqls << payload[:sql]
binds << payload[:binds]
end
end
result = nil
ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
result = block.call
end
[result, sqls, binds]
end
# Makes the adapter execute EXPLAIN for the given queries and bindings.
# Returns a formatted string ready to be logged.
def exec_explain(sqls, binds)
sqls.zip(binds).map do |sql, bind|
[].tap do |msg|
msg << "EXPLAIN for: #{sql}"
unless bind.empty?
bind_msg = bind.map {|col, val| [col.name, val]}.inspect
msg.last << " #{bind_msg}"
end
msg << connection.explain(sql, bind)
end.join("\n")
end.join("\n")
end
end
end

47
activerecord/lib/active_record/relation.rb
View file

@ -10,11 +10,12 @@ module ActiveRecord
MULTI_VALUE_METHODS = [:select, :group, :order, :joins, :where, :having, :bind]
SINGLE_VALUE_METHODS = [:limit, :offset, :lock, :readonly, :from, :reorder, :reverse_order, :uniq]
include FinderMethods, Calculations, SpawnMethods, QueryMethods, Batches
include FinderMethods, Calculations, SpawnMethods, QueryMethods, Batches, Explain
# These are explicitly delegated to improve performance (avoids method_missing)
delegate :to_xml, :to_yaml, :length, :collect, :map, :each, :all?, :include?, :to => :to_a
delegate :table_name, :quoted_table_name, :primary_key, :quoted_primary_key, :connection, :column_hash,:to => :klass
delegate :table_name, :quoted_table_name, :primary_key, :quoted_primary_key,
:connection, :column_hash, :auto_explain_threshold_in_seconds, :to => :klass
attr_reader :table, :klass, :loaded
attr_accessor :extensions, :default_scoped
@ -144,23 +145,35 @@ module ActiveRecord
super
end
def explain
queries = []
callback = lambda do |*args|
payload = args.last
queries << payload[:sql] unless payload[:exception] || %w(SCHEMA EXPLAIN).include?(payload[:name])
end
ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
to_a
end
queries.map do |sql|
"EXPLAIN for: #{sql}\n#{@klass.connection.explain(sql)}"
end.join("\n")
# Runs EXPLAIN on the query or queries triggered by this relation and
# returns the result as a string. The string is formatted imitating the
# ones printed by the database shell.
#
# Note that this method actually runs the queries, since the results of some
# are needed by the next ones when eager loading is going on.
#
# Please see further details in the
# {Active Record Query Interface guide}[http://edgeguides.rubyonrails.org/active_record_querying.html#running-explain].
def explain
results, sqls, binds = collecting_sqls_for_explain { exec_query }
exec_explain(sqls, binds)
end
def to_a
# We monitor here the entire execution rather than individual SELECTs
# because from the point of view of the user fetching the records of a
# relation is a single unit of work. You want to know if this call takes
# too long, not if the individual queries take too long.
#
# It could be the case that none of the queries involved surpass the
# threshold, and at the same time the sum of them all does. The user
# should get a query plan logged in that case.
logging_query_plan do
exec_query
end
end
def exec_query
return @records if loaded?
default_scoped = with_default_scope
@ -191,6 +204,7 @@ module ActiveRecord
@loaded = true
@records
end
private :exec_query
def as_json(options = nil) #:nodoc:
to_a.as_json(options)
@ -543,6 +557,5 @@ module ActiveRecord
# ignore raw_sql_ that is used by Oracle adapter as alias for limit/offset subqueries
string.scan(/([a-zA-Z_][.\w]+).?\./).flatten.map{ |s| s.downcase }.uniq - ['raw_sql_']
end
end
end

91
activerecord/test/cases/explain_test.rb Normal file
View file

@ -0,0 +1,91 @@
require 'cases/helper'
require 'models/car'
require 'active_support/core_ext/string/strip'
if ActiveRecord::Base.connection.supports_explain?
class ExplainTest < ActiveRecord::TestCase
fixtures :cars
def base
ActiveRecord::Base
end
def connection
base.connection
end
def test_logging_query_plan
base.logger.expects(:warn).with do |value|
value.starts_with?('EXPLAIN for:')
end
with_threshold(0) do
Car.where(:name => 'honda').all
end
end
def test_collecting_sqls_for_explain
base.auto_explain_threshold_in_seconds = nil
honda = cars(:honda)
expected_sqls = []
expected_binds = []
callback = lambda do |*args|
payload = args.last
unless base.ignore_explain_notification?(payload)
expected_sqls << payload[:sql]
expected_binds << payload[:binds]
end
end
result = sqls = binds = nil
ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
with_threshold(0) do
result, sqls, binds = base.collecting_sqls_for_explain {
Car.where(:name => 'honda').all
}
end
end
assert_equal result, [honda]
assert_equal expected_sqls, sqls
assert_equal expected_binds, binds
end
def test_exec_explain_with_no_binds
sqls = %w(foo bar)
binds = [[], []]
connection.stubs(:explain).returns('query plan foo', 'query plan bar')
expected = sqls.map {|sql| "EXPLAIN for: #{sql}\nquery plan #{sql}"}.join("\n")
assert_equal expected, base.exec_explain(sqls, binds)
end
def test_exec_explain_with_binds
cols = [Object.new, Object.new]
cols[0].expects(:name).returns('wadus')
cols[1].expects(:name).returns('chaflan')
sqls = %w(foo bar)
binds = [[[cols[0], 1]], [[cols[1], 2]]]
connection.stubs(:explain).returns("query plan foo\n", "query plan bar\n")
expected = <<-SQL.strip_heredoc
EXPLAIN for: #{sqls[0]} [["wadus", 1]]
query plan foo
EXPLAIN for: #{sqls[1]} [["chaflan", 2]]
query plan bar
SQL
assert_equal expected, base.exec_explain(sqls, binds)
end
def with_threshold(threshold)
current_threshold = base.auto_explain_threshold_in_seconds
base.auto_explain_threshold_in_seconds = threshold
yield
ensure
base.auto_explain_threshold_in_seconds = current_threshold
end
end
end

7
railties/CHANGELOG.md
View file

@ -1,6 +1,11 @@
## Rails 3.2.0 (unreleased) ##
* Add DebugExceptions middleware which contains features extracted from ShowExceptions middleware *José Valim*
* New applications get a flag
`config.active_record.auto_explain_threshold_in_seconds` in the evironments
configuration files. With a value of 0.5 in development.rb, and commented
out in production.rb. No mention in test.rb. *fxn*
* Display mounted engine's routes in `rake routes`. *Piotr Sarnacki*
* Display mounted engine's routes in `rake routes` *Piotr Sarnacki*

7
railties/guides/code/getting_started/config/environments/development.rb
View file

@ -22,6 +22,13 @@ Blog::Application.configure do
# Only use best-standards-support built into browsers
config.action_dispatch.best_standards_support = :builtin
# Raise exception on mass assignment protection for ActiveRecord models
config.active_record.mass_assignment_sanitizer = :strict
# Log the query plan for queries taking more than this (works
# with SQLite, MySQL, and PostgreSQL)
config.active_record.auto_explain_threshold_in_seconds = 0.5
# Do not compress assets
config.assets.compress = false

4
railties/guides/code/getting_started/config/environments/production.rb
View file

@ -60,4 +60,8 @@ Blog::Application.configure do
# Send deprecation notices to registered listeners
config.active_support.deprecation = :notify
# Log the query plan for queries taking more than this (works
# with SQLite, MySQL, and PostgreSQL)
# config.active_record.auto_explain_threshold_in_seconds = 0.5
end

2
railties/guides/source/configuring.textile
View file

@ -268,6 +268,8 @@ h4. Configuring Active Record
* +config.active_record.identity_map+ controls whether the identity map is enabled, and is false by default.
* +config.active_record.auto_explain_threshold_in_seconds+ configures the threshold for automatic EXPLAINs (+nil+ disables this feature). Queries taking more than those many seconds get their query plan logged. Default is 0.5 in development mode.
The MySQL adapter adds one additional configuration option:
* +ActiveRecord::ConnectionAdapters::MysqlAdapter.emulate_booleans+ controls whether Active Record will consider all +tinyint(1)+ columns in a MySQL database to be booleans and is true by default.

4
railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
View file

@ -25,6 +25,10 @@
<%- unless options.skip_active_record? -%>
# Raise exception on mass assignment protection for ActiveRecord models
config.active_record.mass_assignment_sanitizer = :strict
# Log the query plan for queries taking more than this (works
# with SQLite, MySQL, and PostgreSQL)
config.active_record.auto_explain_threshold_in_seconds = 0.5
<%- end -%>
# Do not compress assets

6
railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt
View file

@ -60,4 +60,10 @@
# Send deprecation notices to registered listeners
config.active_support.deprecation = :notify
<%- unless options.skip_active_record? -%>
# Log the query plan for queries taking more than this (works
# with SQLite, MySQL, and PostgreSQL)
# config.active_record.auto_explain_threshold_in_seconds = 0.5
<%- end -%>
end

9
railties/test/generators/app_generator_test.rb
View file

@ -336,6 +336,15 @@ class AppGeneratorTest < Rails::Generators::TestCase
end
end
def test_generated_environments_file_for_auto_explain
run_generator [destination_root, "--skip-active-record"]
%w(development test production).each do |env|
assert_file "config/environments/#{env}.rb" do |file|
assert_no_match %r(auto_explain_threshold_in_seconds), file
end
end
end
protected
def action(*args, &block)