implements AR::Base(.|#)silence_auto_explain

5 files changed, 142 insertions, 61 deletions

diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md
index 9ffd085925..f483fdd844 100644
--- a/activerecord/CHANGELOG.md
+++ b/activerecord/CHANGELOG.md
@@ -1,5 +1,8 @@
 ## Rails 3.2.0 (unreleased) ##
 
+*   Implements `silence_auto_explain`. This method allows the user to selectively disable
+    automatic EXPLAINs within a block. *fxn*
+
 *   Implements automatic EXPLAIN logging for slow queries.
 
     A new configuration parameter `config.active_record.auto_explain_threshold_in_seconds`
diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb
index 3d55729318..dcd091aecb 100644
--- a/activerecord/lib/active_record/base.rb
+++ b/activerecord/lib/active_record/base.rb
@@ -2213,7 +2213,7 @@ MSG
     include Associations, NamedScope
     include IdentityMap
     include ActiveModel::SecurePassword
-    extend Explain
+    include Explain
 
     # AutosaveAssociation needs to be included before Transactions, because we want
     # #save_with_autosave_associations to be wrapped inside a transaction.
diff --git a/activerecord/lib/active_record/explain.rb b/activerecord/lib/active_record/explain.rb
index 4d013f0ef4..90aa89a6b5 100644
--- a/activerecord/lib/active_record/explain.rb
+++ b/activerecord/lib/active_record/explain.rb
@@ -1,76 +1,106 @@
 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
+  module Explain
+    extend ActiveSupport::Concern
 
-    # 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
+    module ClassMethods
+      # 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) # :nodoc:
+        threshold = auto_explain_threshold_in_seconds
+        if threshold && !Thread.current[LOGGING_QUERY_PLAN] && !Thread.current[SILENCED]
+          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 > threshold
+            result
+          ensure
+            Thread.current[LOGGING_QUERY_PLAN] = false
+          end
+        else
+          block.call
         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 = %w(SCHEMA EXPLAIN)
-    def ignore_explain_notification?(payload)
-      payload[:exception] || SKIP_EXPLAIN_FOR.include?(payload[:name])
-    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 = %w(SCHEMA EXPLAIN)
+      def ignore_explain_notification?(payload) # :nodoc:
+        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) # :nodoc:
+        sqls  = []
+        binds = []
+        callback = lambda do |*args|
+          payload = args.last
+          unless ignore_explain_notification?(payload)
+            sqls  << payload[:sql]
+            binds << payload[:binds]
+          end
+        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]
+        result = nil
+        ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
+          result = block.call
         end
+
+        [result, sqls, binds]
       end
 
-      result = nil
-      ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
-        result = block.call
+      # Makes the adapter execute EXPLAIN for the given queries and bindings.
+      # Returns a formatted string ready to be logged.
+      def exec_explain(sqls, binds) # :nodoc:
+        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
 
-      [result, sqls, binds]
+      SILENCED = :silence_explain
+
+      # 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 +ActiveRecord::Relation#explain' run.
+      def silence_auto_explain
+        # Implemented as a flag rather that setting the threshold to nil
+        # because we should not depend on a value that may be changed
+        # downwards.
+        Thread.current[SILENCED] = true
+        yield
+      ensure
+        Thread.current[SILENCED] = false
+      end
     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")
+    # A convenience instance method that delegates to the class method of the
+    # same name.
+    def silence_auto_explain(&block)
+      self.class.silence_auto_explain(&block)
     end
   end
 end
diff --git a/activerecord/test/cases/explain_test.rb b/activerecord/test/cases/explain_test.rb
index d3eb9c2cb2..ff460b44eb 100644
--- a/activerecord/test/cases/explain_test.rb
+++ b/activerecord/test/cases/explain_test.rb
@@ -80,6 +80,17 @@ if ActiveRecord::Base.connection.supports_explain?
       assert_equal expected, base.exec_explain(sqls, binds)
     end
 
+    def test_silence_auto_explain
+      base.expects(:collecting_sqls_for_explain).never
+      base.logger.expects(:warn).never
+
+      [base, cars(:honda)].each do |target|
+        target.silence_auto_explain do
+          with_threshold(0) { Car.all }
+        end
+      end
+    end
+
     def with_threshold(threshold)
       current_threshold = base.auto_explain_threshold_in_seconds
       base.auto_explain_threshold_in_seconds = threshold
diff --git a/railties/guides/source/active_record_querying.textile b/railties/guides/source/active_record_querying.textile
index 352f23dc01..0ccaffe45e 100644
--- a/railties/guides/source/active_record_querying.textile
+++ b/railties/guides/source/active_record_querying.textile
@@ -1369,6 +1369,43 @@ EXPLAIN for: SELECT `posts`.* FROM `posts`  WHERE `posts`.`user_id` IN (1)
 
 under MySQL.
 
+h4. 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
+</ruby>
+
+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.
+
+h5. Disabling Automatic EXPLAIN
+
+Automatic EXPLAIN can be selectively silenced with +silence_auto_explain+, which
+is a class and instance method of +ActiveRecord::Base+:
+
+<ruby>
+silence_auto_explain do
+   # no automatic EXPLAIN is triggered here
+end
+</ruby>
+
+That may be useful for queries you know are slow but fine, like a heavyweigth
+report of an admin interface.
+
+As its name suggests, +silence_auto_explain+ only silences automatic EXPLAINs.
+Explicit calls to +ActiveRecord::Relation#explain+ run.
+
 h4. Interpreting EXPLAIN
 
 Interpretation of the output of EXPLAIN is beyond the scope of this guide. The