diff options
Diffstat (limited to 'activerecord')
-rw-r--r-- | activerecord/CHANGELOG.md | 3 | ||||
-rw-r--r-- | activerecord/lib/active_record/base.rb | 2 | ||||
-rw-r--r-- | activerecord/lib/active_record/explain.rb | 150 | ||||
-rw-r--r-- | activerecord/test/cases/explain_test.rb | 11 |
4 files changed, 105 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 |