From cfeac38e2b149d39edeb9add452fbd2ff96679b9 Mon Sep 17 00:00:00 2001 From: Xavier Noria Date: Sun, 4 Dec 2011 11:29:56 -0800 Subject: =?UTF-8?q?implements=20a=20much=20faster=20auto=20EXPLAIN,=20clos?= =?UTF-8?q?es=20#3843=20[Jos=C3=A9=20Valim=20&=20Xavier=20Noria]?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- activerecord/lib/active_record/base.rb | 1 + activerecord/lib/active_record/explain.rb | 87 ++++++++++------------ .../lib/active_record/explain_subscriber.rb | 13 ++++ activerecord/lib/active_record/log_subscriber.rb | 6 +- activerecord/lib/active_record/relation.rb | 10 +-- activerecord/test/cases/explain_test.rb | 60 +++++++-------- 6 files changed, 93 insertions(+), 84 deletions(-) create mode 100644 activerecord/lib/active_record/explain_subscriber.rb 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 -- cgit v1.2.3