Skip to content
Permalink
Browse files

remove AR auto-explain (config.auto_explain_threshold_in_seconds)

We discussed that the auto explain feature is rarely used.
This PR removes only the automatic explain. You can still display
the explain output for any given relation using `ActiveRecord::Relation#explain`.

As a side-effect this should also fix the connection problem during
asset compilation (#9385). The auto explain initializer in the `ActiveRecord::Railtie`
forced a connection.
  • Loading branch information...
senny committed Feb 24, 2013
1 parent 5fc3b87 commit d3688e02ca52c0b72d3092e8498da51e06b7fc58
@@ -1,5 +1,14 @@
## Rails 4.0.0 (unreleased) ##

* The auto explain feature has been removed. This feature was
activated by configuring `config.active_record.auto_explain_threshold_in_seconds`.
The configuration option was deprecated and has no more effect.

You can still use `ActiveRecord::Relation#explain` to see the EXPLAIN output for
any given relation.

*Yves Senn*

* The `:on` option for `after_commit` and `after_rollback` now
accepts an Array of actions.
Fixes #988.
@@ -2,43 +2,7 @@

module ActiveRecord
module Explain
def self.extended(base)
base.mattr_accessor :auto_explain_threshold_in_seconds, instance_accessor: false
end

# If the database adapter supports explain and 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.

#
# The available_queries_for_explain thread variable collects the queries
# to be explained. If the value is nil, it means queries are not being
# currently collected. A false value indicates collecting is turned
# off. Otherwise it is an array of queries.
def logging_query_plan # :nodoc:
return yield unless logger

threshold = auto_explain_threshold_in_seconds
current = Thread.current
if connection.supports_explain? && threshold && current[:available_queries_for_explain].nil?
begin
queries = current[:available_queries_for_explain] = []
start = Time.now
result = yield
logger.warn(exec_explain(queries)) if Time.now - start > threshold
result
ensure
current[:available_queries_for_explain] = nil
end
else
yield
end
end

# Relation#explain needs to be able to collect the queries regardless of
# whether auto explain is enabled. This method serves that purpose.
# Relation#explain needs to be able to collect the queries.
def collecting_queries_for_explain # :nodoc:
current = Thread.current
original, current[:available_queries_for_explain] = current[:available_queries_for_explain], []
@@ -68,20 +32,5 @@ def str.inspect
end
str
end

# Silences automatic EXPLAIN logging for the duration of the block.
#
# This has high priority, no EXPLAINs will be run even if downwards
# the threshold is set to 0.
#
# As the name of the method suggests this only applies to automatic
# EXPLAINs, manual calls to <tt>ActiveRecord::Relation#explain</tt> run.
def silence_auto_explain
current = Thread.current
original, current[:available_queries_for_explain] = current[:available_queries_for_explain], false
yield
ensure
current[:available_queries_for_explain] = original
end
end
end
@@ -33,18 +33,16 @@ module Querying
# 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 = [])
logging_query_plan do
result_set = connection.select_all(sanitize_sql(sql), "#{name} Load", binds)
column_types = {}
result_set = connection.select_all(sanitize_sql(sql), "#{name} Load", binds)
column_types = {}

if result_set.respond_to? :column_types
column_types = result_set.column_types
else
ActiveSupport::Deprecation.warn "the object returned from `select_all` must respond to `column_types`"
end

result_set.map { |record| instantiate(record, column_types) }
if result_set.respond_to? :column_types
column_types = result_set.column_types
else
ActiveSupport::Deprecation.warn "the object returned from `select_all` must respond to `column_types`"
end

result_set.map { |record| instantiate(record, column_types) }
end

# Returns the result of an SQL statement that should only include a COUNT(*) in the SELECT part.
@@ -57,10 +55,8 @@ def find_by_sql(sql, binds = [])
#
# Product.count_by_sql "SELECT COUNT(*) FROM sales s, customers c WHERE s.customer_id = c.id"
def count_by_sql(sql)
logging_query_plan do
sql = sanitize_conditions(sql)
connection.select_value(sql, "#{name} Count").to_i
end
sql = sanitize_conditions(sql)
connection.select_value(sql, "#{name} Count").to_i
end
end
end
@@ -112,7 +112,18 @@ class Railtie < Rails::Railtie # :nodoc:
`config/application.rb` file and any `mass_assignment_sanitizer` options
from your `config/environments/*.rb` files.
See http://guides.rubyonrails.org/security.html#mass-assignment for more information
See http://guides.rubyonrails.org/security.html#mass-assignment for more information.
EOF
end

unless app.config.active_record.delete(:auto_explain_threshold_in_seconds).nil?
ActiveSupport::Deprecation.warn <<-EOF.strip_heredoc, []
The Active Record auto explain feature has been removed.
To disable this message remove the `active_record.auto_explain_threshold_in_seconds`
option from the `config/environments/*.rb` config file.
See http://guides.rubyonrails.org/4_0_release_notes.html for more information.
EOF
end

@@ -124,7 +135,7 @@ class Railtie < Rails::Railtie # :nodoc:
To disable this message remove the `observers` option from your
`config/application.rb` or from your initializers.
See http://guides.rubyonrails.org/4_0_release_notes.html for more information
See http://guides.rubyonrails.org/4_0_release_notes.html for more information.
EOF
end
ensure
@@ -146,13 +157,6 @@ class Railtie < Rails::Railtie # :nodoc:
end
end

initializer "active_record.validate_explain_support" do |app|
if app.config.active_record[:auto_explain_threshold_in_seconds] &&
!ActiveRecord::Base.connection.supports_explain?
warn "auto_explain_threshold_in_seconds is set but will be ignored because your adapter does not support this feature. Please unset the configuration to avoid this warning."
end
end

# Expose database runtime to controller for logging.
initializer "active_record.log_runtime" do |app|
require "active_record/railties/controller_runtime"
@@ -444,17 +444,7 @@ def delete(id_or_array)
#
# Post.where(published: true).load # => #<ActiveRecord::Relation>
def load
unless loaded?
# 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 { exec_queries }
end
exec_queries unless loaded?

self
end
@@ -12,7 +12,7 @@ module Delegation # :nodoc:

delegate :to_xml, :to_yaml, :length, :collect, :map, :each, :all?, :include?, :to_ary, :to => :to_a
delegate :table_name, :quoted_table_name, :primary_key, :quoted_primary_key,
:connection, :columns_hash, :auto_explain_threshold_in_seconds, :to => :klass
:connection, :columns_hash, :to => :klass

module ClassSpecificRelation
extend ActiveSupport::Concern
@@ -14,46 +14,9 @@ def connection
base.connection
end

def test_logging_query_plan_with_logger
base.logger.expects(:warn).with do |message|
message.starts_with?('EXPLAIN for:')
end

with_threshold(0) do
Car.where(:name => 'honda').to_a
end
end

def test_logging_query_plan_without_logger
original = base.logger
base.logger = nil

class << base.logger
def warn; raise "Should not be called" end
end

with_threshold(0) do
car = Car.where(:name => 'honda').first
assert_equal 'honda', car.name
end
ensure
base.logger = original
end

def test_collect_queries_for_explain
base.auto_explain_threshold_in_seconds = nil
queries = Thread.current[:available_queries_for_explain] = []

with_threshold(0) do
Car.where(:name => 'honda').to_a
end

sql, binds = queries[0]
assert_match "SELECT", sql
assert_match "honda", sql
assert_equal [], binds
ensure
Thread.current[:available_queries_for_explain] = nil
def test_relation_explain
message = Car.where(:name => 'honda').explain
assert_match(/^EXPLAIN for:/, message)
end

def test_collecting_queries_for_explain
@@ -68,16 +31,6 @@ def test_collecting_queries_for_explain
assert_equal [cars(:honda)], result
end

def test_logging_query_plan_when_counting_by_sql
base.logger.expects(:warn).with do |message|
message.starts_with?('EXPLAIN for:')
end

with_threshold(0) do
Car.count_by_sql "SELECT COUNT(*) FROM cars WHERE name = 'honda'"
end
end

def test_exec_explain_with_no_binds
sqls = %w(foo bar)
binds = [[], []]
@@ -113,25 +66,8 @@ def test_unsupported_connection_adapter

base.logger.expects(:warn).never

with_threshold(0) do
Car.where(:name => 'honda').to_a
end
end

def test_silence_auto_explain
base.expects(:collecting_sqls_for_explain).never
base.logger.expects(:warn).never
base.silence_auto_explain do
with_threshold(0) { Car.all.to_a }
end
Car.where(:name => 'honda').to_a
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
@@ -22,10 +22,6 @@
# Only use best-standards-support built into browsers.
config.action_dispatch.best_standards_support = :builtin

# 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

# Raise an error on page load if there are pending migrations
config.active_record.migration_error = :page_load

@@ -72,10 +72,6 @@
# 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

# Disable automatic flushing of the log to improve performance.
# config.autoflush_log = false

@@ -1609,45 +1609,6 @@ EXPLAIN for: SELECT `posts`.* FROM `posts` WHERE `posts`.`user_id` IN (1)

under MySQL.

### Automatic EXPLAIN

Active Record is able to run EXPLAIN automatically on slow queries and log its
output. This feature is controlled by the configuration parameter

```ruby
config.active_record.auto_explain_threshold_in_seconds
```

If set to a number, any query exceeding those many seconds will have its EXPLAIN
automatically triggered and logged. In the case of relations, the threshold is
compared to the total time needed to fetch records. So, a relation is seen as a
unit of work, no matter whether the implementation of eager loading involves
several queries under the hood.

A threshold of `nil` disables automatic EXPLAINs.

The default threshold in development mode is 0.5 seconds, and `nil` in test and
production modes.

INFO. Automatic EXPLAIN gets disabled if Active Record has no logger, regardless
of the value of the threshold.

#### Disabling Automatic EXPLAIN

Automatic EXPLAIN can be selectively silenced with `ActiveRecord::Base.silence_auto_explain`:

```ruby
ActiveRecord::Base.silence_auto_explain do
# no automatic EXPLAIN is triggered here
end
```

That may be useful for queries you know are slow but fine, like a heavyweight
report of an admin interface.

As its name suggests, `silence_auto_explain` only silences automatic EXPLAINs.
Explicit calls to `ActiveRecord::Relation#explain` run.

### Interpreting EXPLAIN

Interpretation of the output of EXPLAIN is beyond the scope of this guide. The
@@ -268,8 +268,6 @@ config.middleware.delete "Rack::MethodOverride"

* `config.active_record.lock_optimistically` controls whether Active Record will use optimistic locking and is true by default.

* `config.active_record.auto_explain_threshold_in_seconds` configures the threshold for automatic EXPLAINs (`nil` disables this feature). Queries exceeding the threshold get their query plan logged. Default is 0.5 in development mode.

* +config.active_record.cache_timestamp_format+ controls the format of the timestamp value in the cache key. Default is +:number+.

The MySQL adapter adds one additional configuration option:
@@ -20,10 +20,6 @@
config.active_support.deprecation = :log

<%- 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

# Raise an error on page load if there are pending migrations
config.active_record.migration_error = :page_load
<%- end -%>
@@ -76,12 +76,6 @@
# 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 -%>

# Disable automatic flushing of the log to improve performance.
# config.autoflush_log = false

Oops, something went wrong.

1 comment on commit d3688e0

@korny

This comment has been minimized.

Copy link
Contributor

korny commented on d3688e0 Mar 3, 2013

this should also fix the connection problem during asset compilation

\o/

Please sign in to comment.
You can’t perform that action at this time.