Merge pull request #9400 from senny/remove_auto_explain_threshold_in_…

…seconds remove config.auto_explain_threshold_in_seconds
rails · Feb 24, 2013 · d65376f · d65376f
2 parents 40111c5 + d3688e0
commit d65376f
Show file tree

Hide file tree

Showing 14 changed files with 39 additions and 223 deletions.
diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md
@@ -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.

diff --git a/activerecord/lib/active_record/explain.rb b/activerecord/lib/active_record/explain.rb
@@ -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
diff --git a/activerecord/lib/active_record/querying.rb b/activerecord/lib/active_record/querying.rb
@@ -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
diff --git a/activerecord/lib/active_record/railtie.rb b/activerecord/lib/active_record/railtie.rb
@@ -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"

diff --git a/activerecord/lib/active_record/relation.rb b/activerecord/lib/active_record/relation.rb
@@ -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

diff --git a/activerecord/lib/active_record/relation/delegation.rb b/activerecord/lib/active_record/relation/delegation.rb
@@ -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

diff --git a/activerecord/test/cases/explain_test.rb b/activerecord/test/cases/explain_test.rb
@@ -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
diff --git a/guides/code/getting_started/config/environments/development.rb b/guides/code/getting_started/config/environments/development.rb
@@ -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
 

diff --git a/guides/code/getting_started/config/environments/production.rb b/guides/code/getting_started/config/environments/production.rb
@@ -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
 

diff --git a/guides/source/active_record_querying.md b/guides/source/active_record_querying.md
@@ -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

diff --git a/guides/source/configuring.md b/guides/source/configuring.md
@@ -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:

diff --git a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
@@ -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 -%>

diff --git a/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt
@@ -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