implements automatic EXPLAIN logging for slow queries

8 files changed, 212 insertions, 95 deletions

diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb
index 11469f7e43..3d55729318 100644
--- a/activerecord/lib/active_record/base.rb
+++ b/activerecord/lib/active_record/base.rb
@@ -433,6 +433,11 @@ module ActiveRecord #:nodoc:
     class_attribute :default_scopes, :instance_writer => false
     self.default_scopes = []
 
+    # If a query takes longer than these many seconds we log its query plan
+    # automatically. nil disables this feature.
+    class_attribute :auto_explain_threshold_in_seconds, :instance_writer => false
+    self.auto_explain_threshold_in_seconds = nil
+
     class_attribute :_attr_readonly, :instance_writer => false
     self._attr_readonly = []
 
@@ -484,7 +489,9 @@ module ActiveRecord #:nodoc:
       #   Post.find_by_sql ["SELECT title FROM posts WHERE author = ? AND created > ?", author_id, start_date]
       #   > [#<Post:0x36bff9c @attributes={"title"=>"The Cheap Man Buys Twice"}>, ...]
       def find_by_sql(sql, binds = [])
-        connection.select_all(sanitize_sql(sql), "#{name} Load", binds).collect! { |record| instantiate(record) }
+        logging_query_plan do
+          connection.select_all(sanitize_sql(sql), "#{name} Load", binds).collect! { |record| instantiate(record) }
+        end
       end
 
       # Creates an object (or multiple objects) and saves it to the database, if validations pass.
@@ -2206,6 +2213,7 @@ MSG
     include Associations, NamedScope
     include IdentityMap
     include ActiveModel::SecurePassword
+    extend 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/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
index 1a4cc93d2d..5a2493f69d 100644
--- a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
@@ -142,6 +142,12 @@ module ActiveRecord
         false
       end
 
+      # Does this adapter support explain? As of this writing sqlite3,
+      # mysql2, and postgresql are the only ones that do.
+      def supports_explain?
+        false
+      end
+
       # QUOTING ==================================================
 
       # Override to return the quoted table name. Defaults to column quoting.
diff --git a/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb
index f143fd348e..7f5ddf77d6 100644
--- a/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb
@@ -225,80 +225,6 @@ module ActiveRecord
 
       # DATABASE STATEMENTS ======================================
 
-      def explain(arel)
-        sql     = "EXPLAIN #{to_sql(arel)}"
-        start   = Time.now
-        result  = exec_query(sql, 'EXPLAIN')
-        elapsed = Time.now - start
-
-        ExplainPrettyPrinter.new.pp(result, elapsed)
-      end
-
-      class ExplainPrettyPrinter # :nodoc:
-        # Pretty prints the result of a EXPLAIN in a way that resembles the output of the
-        # MySQL shell:
-        #
-        #   +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
-        #   | id | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra       |
-        #   +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
-        #   |  1 | SIMPLE      | users | const | PRIMARY       | PRIMARY | 4       | const |    1 |             |
-        #   |  1 | SIMPLE      | posts | ALL   | NULL          | NULL    | NULL    | NULL  |    1 | Using where |
-        #   +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
-        #   2 rows in set (0.00 sec)
-        #
-        # This is an exercise in Ruby hyperrealism :).
-        def pp(result, elapsed)
-          widths    = compute_column_widths(result)
-          separator = build_separator(widths)
-
-          pp = []
-
-          pp << separator
-          pp << build_cells(result.columns, widths)
-          pp << separator
-
-          result.rows.each do |row|
-            pp << build_cells(row, widths)
-          end
-
-          pp << separator
-          pp << build_footer(result.rows.length, elapsed)
-
-          pp.join("\n") + "\n"
-        end
-
-        private
-
-        def compute_column_widths(result)
-          [].tap do |widths|
-            result.columns.each_with_index do |column, i|
-              cells_in_column = [column] + result.rows.map {|r| r[i].nil? ? 'NULL' : r[i].to_s}
-              widths << cells_in_column.map(&:length).max
-            end
-          end
-        end
-
-        def build_separator(widths)
-          padding = 1
-          '+' + widths.map {|w| '-' * (w + (padding*2))}.join('+') + '+'
-        end
-
-        def build_cells(items, widths)
-          cells = []
-          items.each_with_index do |item, i|
-            item = 'NULL' if item.nil?
-            justifier = item.is_a?(Numeric) ? 'rjust' : 'ljust'
-            cells << item.to_s.send(justifier, widths[i])
-          end
-          '| ' + cells.join(' | ') + ' |'
-        end
-
-        def build_footer(nrows, elapsed)
-          rows_label = nrows == 1 ? 'row' : 'rows'
-          "#{nrows} #{rows_label} in set (%.2f sec)" % elapsed
-        end
-      end
-
       # Executes the SQL statement in the context of this connection.
       def execute(sql, name = nil)
         if name == :skip_logging
diff --git a/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb b/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb
index 95f254ddd2..626571a948 100644
--- a/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb
@@ -35,6 +35,10 @@ module ActiveRecord
         configure_connection
       end
 
+      def supports_explain?
+        true
+      end
+
       # HELPER METHODS ===========================================
 
       def each_hash(result) # :nodoc:
@@ -93,6 +97,80 @@ module ActiveRecord
 
       # DATABASE STATEMENTS ======================================
 
+      def explain(arel, binds = [])
+        sql     = "EXPLAIN #{to_sql(arel)}"
+        start   = Time.now
+        result  = exec_query(sql, 'EXPLAIN', binds)
+        elapsed = Time.now - start
+
+        ExplainPrettyPrinter.new.pp(result, elapsed)
+      end
+
+      class ExplainPrettyPrinter # :nodoc:
+        # Pretty prints the result of a EXPLAIN in a way that resembles the output of the
+        # MySQL shell:
+        #
+        #   +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
+        #   | id | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra       |
+        #   +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
+        #   |  1 | SIMPLE      | users | const | PRIMARY       | PRIMARY | 4       | const |    1 |             |
+        #   |  1 | SIMPLE      | posts | ALL   | NULL          | NULL    | NULL    | NULL  |    1 | Using where |
+        #   +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
+        #   2 rows in set (0.00 sec)
+        #
+        # This is an exercise in Ruby hyperrealism :).
+        def pp(result, elapsed)
+          widths    = compute_column_widths(result)
+          separator = build_separator(widths)
+
+          pp = []
+
+          pp << separator
+          pp << build_cells(result.columns, widths)
+          pp << separator
+
+          result.rows.each do |row|
+            pp << build_cells(row, widths)
+          end
+
+          pp << separator
+          pp << build_footer(result.rows.length, elapsed)
+
+          pp.join("\n") + "\n"
+        end
+
+        private
+
+        def compute_column_widths(result)
+          [].tap do |widths|
+            result.columns.each_with_index do |column, i|
+              cells_in_column = [column] + result.rows.map {|r| r[i].nil? ? 'NULL' : r[i].to_s}
+              widths << cells_in_column.map(&:length).max
+            end
+          end
+        end
+
+        def build_separator(widths)
+          padding = 1
+          '+' + widths.map {|w| '-' * (w + (padding*2))}.join('+') + '+'
+        end
+
+        def build_cells(items, widths)
+          cells = []
+          items.each_with_index do |item, i|
+            item = 'NULL' if item.nil?
+            justifier = item.is_a?(Numeric) ? 'rjust' : 'ljust'
+            cells << item.to_s.send(justifier, widths[i])
+          end
+          '| ' + cells.join(' | ') + ' |'
+        end
+
+        def build_footer(nrows, elapsed)
+          rows_label = nrows == 1 ? 'row' : 'rows'
+          "#{nrows} #{rows_label} in set (%.2f sec)" % elapsed
+        end
+      end
+
       # FIXME: re-enable the following once a "better" query_cache solution is in core
       #
       # The overrides below perform much better than the originals in AbstractAdapter
diff --git a/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb b/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
index 2f01fbb829..6b742ed858 100644
--- a/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
@@ -390,6 +390,11 @@ module ActiveRecord
         true
       end
 
+      # Returns true.
+      def supports_explain?
+        true
+      end
+
       # Returns the configured supported identifier length supported by PostgreSQL
       def table_alias_length
         @table_alias_length ||= query('SHOW max_identifier_length')[0][0].to_i
@@ -514,9 +519,9 @@ module ActiveRecord
 
       # DATABASE STATEMENTS ======================================
 
-      def explain(arel)
+      def explain(arel, binds = [])
         sql = "EXPLAIN #{to_sql(arel)}"
-        ExplainPrettyPrinter.new.pp(exec_query(sql))
+        ExplainPrettyPrinter.new.pp(exec_query(sql, 'EXPLAIN', binds))
       end
 
       class ExplainPrettyPrinter # :nodoc:
diff --git a/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb b/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb
index c11f82a33f..b8e91a2aea 100644
--- a/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb
@@ -122,6 +122,11 @@ module ActiveRecord
         true
       end
 
+      # Returns true.
+      def supports_explain?
+        true
+      end
+
       def requires_reloading?
         true
       end
@@ -219,9 +224,9 @@ module ActiveRecord
 
       # DATABASE STATEMENTS ======================================
 
-      def explain(arel)
+      def explain(arel, binds = [])
         sql = "EXPLAIN QUERY PLAN #{to_sql(arel)}"
-        ExplainPrettyPrinter.new.pp(exec_query(sql, 'EXPLAIN'))
+        ExplainPrettyPrinter.new.pp(exec_query(sql, 'EXPLAIN', binds))
       end
 
       class ExplainPrettyPrinter
diff --git a/activerecord/lib/active_record/explain.rb b/activerecord/lib/active_record/explain.rb
new file mode 100644
index 0000000000..ab3a45ae53
--- /dev/null
+++ b/activerecord/lib/active_record/explain.rb
@@ -0,0 +1,76 @@
+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
+
+    # 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
+        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 = %(SCHEMA EXPLAIN)
+    def ignore_explain_notification?(payload)
+      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)
+      sqls  = []
+      binds = []
+      callback = lambda do |*args|
+        payload = args.last
+        unless ignore_explain_notification?(payload)
+          sqls  << payload[:sql]
+          binds << payload[:binds]
+        end
+      end
+
+      result = nil
+      ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
+        result = block.call
+      end
+
+      [result, sqls, binds]
+    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")
+    end
+  end
+end
diff --git a/activerecord/lib/active_record/relation.rb b/activerecord/lib/active_record/relation.rb
index 0c32ad5139..e69e1aeaf8 100644
--- a/activerecord/lib/active_record/relation.rb
+++ b/activerecord/lib/active_record/relation.rb
@@ -10,11 +10,12 @@ module ActiveRecord
     MULTI_VALUE_METHODS = [:select, :group, :order, :joins, :where, :having, :bind]
     SINGLE_VALUE_METHODS = [:limit, :offset, :lock, :readonly, :from, :reorder, :reverse_order, :uniq]
 
-    include FinderMethods, Calculations, SpawnMethods, QueryMethods, Batches
+    include FinderMethods, Calculations, SpawnMethods, QueryMethods, Batches, Explain
 
     # These are explicitly delegated to improve performance (avoids method_missing)
     delegate :to_xml, :to_yaml, :length, :collect, :map, :each, :all?, :include?, :to => :to_a
-    delegate :table_name, :quoted_table_name, :primary_key, :quoted_primary_key, :connection, :column_hash,:to => :klass
+    delegate :table_name, :quoted_table_name, :primary_key, :quoted_primary_key,
+             :connection, :column_hash, :auto_explain_threshold_in_seconds, :to => :klass
 
     attr_reader :table, :klass, :loaded
     attr_accessor :extensions, :default_scoped
@@ -144,23 +145,35 @@ module ActiveRecord
         super
     end
 
-    def explain
-      queries = []
-      callback = lambda do |*args|
-        payload = args.last
-        queries << payload[:sql] unless payload[:exception] || %w(SCHEMA EXPLAIN).include?(payload[:name])
-      end
+    # Runs EXPLAIN on the query or queries triggered by this relation and
+    # returns the result as a string. The string is formatted imitating the
+    # ones printed by the database shell.
+    #
+    # Note that this method actually runs the queries, since the results of some
+    # are needed by the next ones when eager loading is going on.
+    #
+    # Please see further details in the
+    # {Active Record Query Interface guide}[http://edgeguides.rubyonrails.org/active_record_querying.html#running-explain].
+   def explain
+      results, sqls, binds = collecting_sqls_for_explain { exec_query }
+      exec_explain(sqls, binds)
+    end
 
-      ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
-        to_a
+    def to_a
+      # We monitor here the entire execution rather than individual SELECTs
+      # because from the point of view of the user fetching the records of a
+      # relation is a single unit of work. You want to know if this call takes
+      # too long, not if the individual queries take too long.
+      #
+      # It could be the case that none of the queries involved surpass the
+      # 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
       end
-
-      queries.map do |sql|
-        "EXPLAIN for: #{sql}\n#{@klass.connection.explain(sql)}"
-      end.join("\n")
     end
 
-    def to_a
+    def exec_query
       return @records if loaded?
 
       default_scoped = with_default_scope
@@ -191,6 +204,7 @@ module ActiveRecord
       @loaded = true
       @records
     end
+    private :exec_query
 
     def as_json(options = nil) #:nodoc:
       to_a.as_json(options)
@@ -543,6 +557,5 @@ module ActiveRecord
       # ignore raw_sql_ that is used by Oracle adapter as alias for limit/offset subqueries
       string.scan(/([a-zA-Z_][.\w]+).?\./).flatten.map{ |s| s.downcase }.uniq - ['raw_sql_']
     end
-
   end
 end