implements a much faster auto EXPLAIN, closes #3843 [José Valim & Xavier Noria]

This commit vastly reduces the impact of auto
explain logging when enabled, while keeping
a negligible cost when disabled.

The first implementation was based on the idea
of subscribing to "sql.active_record" when
needed, and unsubscribing once done. This is
the idea behind AR::Relation#explain. Subscribe,
collect, unsubscribe.

But with the current implementation of notifications
unsubscribing is costly, because it wipes an internal
cache and that puts a penalty on the next event.

So we are switching to an approach where a long-running
subscriber is listening. Instead of collecting the
queries with a closure in a dedicated subscriber, now
we setup a thread local.

If the feature is disabled by setting the threshold
to nil, the subscriber will call a method that does
nothing. That's totally cheap.

6 files changed, 93 insertions, 84 deletions

diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb
index 3d55729318..7a3fe37dee 100644
--- a/activerecord/lib/active_record/base.rb
+++ b/activerecord/lib/active_record/base.rb
@@ -27,6 +27,7 @@ require 'active_support/deprecation'
 require 'arel'
 require 'active_record/errors'
 require 'active_record/log_subscriber'
+require 'active_record/explain_subscriber'
 
 module ActiveRecord #:nodoc:
   # = Active Record
diff --git a/activerecord/lib/active_record/explain.rb b/activerecord/lib/active_record/explain.rb
index abe6fff5d5..6dff53d959 100644
--- a/activerecord/lib/active_record/explain.rb
+++ b/activerecord/lib/active_record/explain.rb
@@ -1,68 +1,65 @@
 module ActiveRecord
   module Explain
-    # 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:
+    #
+    # 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:
       threshold = auto_explain_threshold_in_seconds
-      if threshold && !Thread.current[LOGGING_QUERY_PLAN] && !Thread.current[SILENCED]
+      current   = Thread.current
+      if threshold && current[:available_queries_for_explain].nil?
         begin
-          Thread.current[LOGGING_QUERY_PLAN] = true
+          queries = current[:available_queries_for_explain] = []
           start = Time.now
-          result, sqls, binds = collecting_sqls_for_explain(&block)
-          logger.warn(exec_explain(sqls, binds)) if Time.now - start > threshold
+          result = yield
+          logger.warn(exec_explain(queries)) if Time.now - start > threshold
           result
         ensure
-          Thread.current[LOGGING_QUERY_PLAN] = false
+          current[:available_queries_for_explain] = nil
         end
       else
         yield
       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) # :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 # :nodoc:
-      sqls  = []
-      binds = []
-      callback = lambda do |*args|
-        payload = args.last
-        unless ignore_explain_notification?(payload)
-          sqls  << payload[:sql]
-          binds << payload[:binds]
+    # This method receives payloads from the explain subscriber and is
+    # responsible for collecting or ignoring them.
+    def collect_queries_for_explain(payload) # :nodoc:
+      if queries = Thread.current[:available_queries_for_explain]
+        unless ignore_payload_for_explain?(payload)
+          queries << payload.values_at(:sql, :binds)
         end
       end
+    end
 
-      result = nil
-      ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
-        result = yield
-      end
+    # Relation#explain needs to be able to collect the queries regardless of
+    # whether auto explain is enabled. This method serves that purpose.
+    def collecting_queries_for_explain # :nodoc:
+      current = Thread.current
+      original, current[:available_queries_for_explain] = current[:available_queries_for_explain], []
+      return yield, current[:available_queries_for_explain]
+    ensure
+      # Note that the return value above does not depend on this assigment.
+      current[:available_queries_for_explain] = original
+    end
 
-      [result, sqls, binds]
+    # 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_payload_for_explain?(payload) # :nodoc:
+      payload[:exception] || SKIP_EXPLAIN_FOR.include?(payload[:name])
     end
 
-    # Makes the adapter execute EXPLAIN for the given queries and bindings.
+    # Makes the adapter execute EXPLAIN for the tuples of queries and bindings.
     # Returns a formatted string ready to be logged.
-    def exec_explain(sqls, binds) # :nodoc:
-      sqls.zip(binds).map do |sql, bind|
+    def exec_explain(queries) # :nodoc:
+      queries && queries.map do |sql, bind|
         [].tap do |msg|
           msg << "EXPLAIN for: #{sql}"
           unless bind.empty?
@@ -74,8 +71,6 @@ module ActiveRecord
       end.join("\n")
     end
 
-    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
@@ -84,13 +79,11 @@ module ActiveRecord
     # 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
+      current = Thread.current
+      original, current[:available_queries_for_explain] = current[:available_queries_for_explain], false
       yield
     ensure
-      Thread.current[SILENCED] = false
+      current[:available_queries_for_explain] = original
     end
   end
 end
diff --git a/activerecord/lib/active_record/explain_subscriber.rb b/activerecord/lib/active_record/explain_subscriber.rb
new file mode 100644
index 0000000000..8a88be6761
--- /dev/null
+++ b/activerecord/lib/active_record/explain_subscriber.rb
@@ -0,0 +1,13 @@
+module ActiveRecord
+  class ExplainSubscriber < ActiveSupport::LogSubscriber
+    def sql(event)
+      ActiveRecord::Base.collect_queries_for_explain(event.payload)
+    end
+
+    def logger
+      ActiveRecord::Base.logger
+    end
+
+    attach_to :active_record
+  end
+end
diff --git a/activerecord/lib/active_record/log_subscriber.rb b/activerecord/lib/active_record/log_subscriber.rb
index 3a015ee8c2..a25f2c7bca 100644
--- a/activerecord/lib/active_record/log_subscriber.rb
+++ b/activerecord/lib/active_record/log_subscriber.rb
@@ -26,9 +26,9 @@ module ActiveRecord
 
       return if 'SCHEMA' == payload[:name]
 
-      name    = '%s (%.1fms)' % [payload[:name], event.duration]
-      sql     = payload[:sql].squeeze(' ')
-      binds   = nil
+      name  = '%s (%.1fms)' % [payload[:name], event.duration]
+      sql   = payload[:sql].squeeze(' ')
+      binds = nil
 
       unless (payload[:binds] || []).empty?
         binds = "  " + payload[:binds].map { |col,v|
diff --git a/activerecord/lib/active_record/relation.rb b/activerecord/lib/active_record/relation.rb
index 30cd8679fe..2897e354c5 100644
--- a/activerecord/lib/active_record/relation.rb
+++ b/activerecord/lib/active_record/relation.rb
@@ -155,8 +155,8 @@ module ActiveRecord
     # Please see further details in the
     # {Active Record Query Interface guide}[http://edgeguides.rubyonrails.org/active_record_querying.html#running-explain].
     def explain
-      _, sqls, binds = collecting_sqls_for_explain { exec_query }
-      exec_explain(sqls, binds)
+      _, queries = collecting_queries_for_explain { exec_queries }
+      exec_explain(queries)
     end
 
     def to_a
@@ -169,11 +169,11 @@ module ActiveRecord
       # 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
+        exec_queries
       end
     end
 
-    def exec_query
+    def exec_queries
       return @records if loaded?
 
       default_scoped = with_default_scope
@@ -204,7 +204,7 @@ module ActiveRecord
       @loaded = true
       @records
     end
-    private :exec_query
+    private :exec_queries
 
     def as_json(options = nil) #:nodoc:
       to_a.as_json(options)
diff --git a/activerecord/test/cases/explain_test.rb b/activerecord/test/cases/explain_test.rb
index 0284cca920..6ae6f83446 100644
--- a/activerecord/test/cases/explain_test.rb
+++ b/activerecord/test/cases/explain_test.rb
@@ -15,8 +15,8 @@ if ActiveRecord::Base.connection.supports_explain?
     end
 
     def test_logging_query_plan
-      base.logger.expects(:warn).with do |value|
-        value.starts_with?('EXPLAIN for:')
+      base.logger.expects(:warn).with do |message|
+        message.starts_with?('EXPLAIN for:')
       end
 
       with_threshold(0) do
@@ -24,41 +24,42 @@ if ActiveRecord::Base.connection.supports_explain?
       end
     end
 
-    def test_collecting_sqls_for_explain
+    def test_collect_queries_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
+      queries = Thread.current[:available_queries_for_explain] = []
+
+      with_threshold(0) do
+        Car.where(:name => 'honda').all
       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
+      sql, binds = queries[0]
+      assert_match "SELECT", sql
+      assert_match "honda", sql
+      assert_equal [], binds
+    ensure
+      Thread.current[:available_queries_for_explain] = nil
+    end
+
+    def test_collecting_queries_for_explain
+      result, queries = ActiveRecord::Base.collecting_queries_for_explain do
+        Car.where(:name => 'honda').all
       end
 
-      assert_equal result, [honda]
-      assert_equal expected_sqls, sqls
-      assert_equal expected_binds, binds
+      sql, binds = queries[0]
+      assert_match "SELECT", sql
+      assert_match "honda", sql
+      assert_equal [], binds
+      assert_equal [cars(:honda)], result
     end
 
     def test_exec_explain_with_no_binds
-      sqls  = %w(foo bar)
-      binds = [[], []]
+      sqls    = %w(foo bar)
+      binds   = [[], []]
+      queries = sqls.zip(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)
+      assert_equal expected, base.exec_explain(queries)
     end
 
     def test_exec_explain_with_binds
@@ -66,8 +67,9 @@ if ActiveRecord::Base.connection.supports_explain?
       cols[0].expects(:name).returns('wadus')
       cols[1].expects(:name).returns('chaflan')
 
-      sqls  = %w(foo bar)
-      binds = [[[cols[0], 1]], [[cols[1], 2]]]
+      sqls    = %w(foo bar)
+      binds   = [[[cols[0], 1]], [[cols[1], 2]]]
+      queries = sqls.zip(binds)
 
       connection.stubs(:explain).returns("query plan foo\n", "query plan bar\n")
       expected = <<-SQL.strip_heredoc
@@ -77,7 +79,7 @@ if ActiveRecord::Base.connection.supports_explain?
         EXPLAIN for: #{sqls[1]} [["chaflan", 2]]
         query plan bar
       SQL
-      assert_equal expected, base.exec_explain(sqls, binds)
+      assert_equal expected, base.exec_explain(queries)
     end
 
     def test_silence_auto_explain