Skip to content
Browse files

Merge branch 'explain'

  • Loading branch information...
2 parents 0ec0c9a + cfeac38 commit d59bfeb1197960277f66ddb76ca544d8472ab8af @fxn fxn committed
View
1 activerecord/lib/active_record/base.rb
@@ -27,6 +27,7 @@
require 'arel'
require 'active_record/errors'
require 'active_record/log_subscriber'
+require 'active_record/explain_subscriber'
module ActiveRecord #:nodoc:
# = Active Record
View
87 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 @@ def exec_explain(sqls, binds) # :nodoc:
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 @@ def exec_explain(sqls, binds) # :nodoc:
# 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
View
13 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
View
6 activerecord/lib/active_record/log_subscriber.rb
@@ -26,9 +26,9 @@ def sql(event)
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|
View
10 activerecord/lib/active_record/relation.rb
@@ -155,8 +155,8 @@ def respond_to?(method, include_private = false)
# 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 @@ def to_a
# 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 @@ def exec_query
@loaded = true
@records
end
- private :exec_query
+ private :exec_queries
def as_json(options = nil) #:nodoc:
to_a.as_json(options)
View
60 activerecord/test/cases/explain_test.rb
@@ -15,8 +15,8 @@ def connection
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 @@ def test_logging_query_plan
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 @@ def test_exec_explain_with_binds
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 @@ def test_exec_explain_with_binds
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

0 comments on commit d59bfeb

Please sign in to comment.
Something went wrong with that request. Please try again.