diff options
Diffstat (limited to 'activerecord/lib/active_record')
| -rw-r--r-- | activerecord/lib/active_record/base.rb | 1 | ||||
| -rw-r--r-- | activerecord/lib/active_record/explain.rb | 87 | ||||
| -rw-r--r-- | activerecord/lib/active_record/explain_subscriber.rb | 13 | ||||
| -rw-r--r-- | activerecord/lib/active_record/log_subscriber.rb | 6 | ||||
| -rw-r--r-- | activerecord/lib/active_record/relation.rb | 10 |
5 files changed, 62 insertions, 55 deletions
diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb index 9bc0023539..7efdcc8cb9 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) |