implements automatic EXPLAIN logging for slow queries

18 files changed, 354 insertions, 96 deletions

diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md
index f798b03ea1..9ffd085925 100644
--- a/activerecord/CHANGELOG.md
+++ b/activerecord/CHANGELOG.md
@@ -1,5 +1,16 @@
 ## Rails 3.2.0 (unreleased) ##
 
+*   Implements automatic EXPLAIN logging for slow queries.
+
+    A new configuration parameter `config.active_record.auto_explain_threshold_in_seconds`
+    determines what's to be considered a slow query. Setting that to `nil` disables
+    this feature. Defaults are 0.5 in development mode, and `nil` in test and production
+    modes.
+
+    As of this writing there's support for SQLite, MySQL (mysql2 adapter), and
+    PostgreSQL.
+
+    *fxn*
 
 *   Implemented ActiveRecord::Relation#pluck method
 
diff --git a/activerecord/lib/active_record.rb b/activerecord/lib/active_record.rb
index 978e415e58..b1377c24dd 100644
--- a/activerecord/lib/active_record.rb
+++ b/activerecord/lib/active_record.rb
@@ -50,6 +50,7 @@ module ActiveRecord
       autoload :PredicateBuilder
       autoload :SpawnMethods
       autoload :Batches
+      autoload :Explain
     end
 
     autoload :Base
@@ -75,6 +76,7 @@ module ActiveRecord
     autoload :Transactions
     autoload :Validations
     autoload :IdentityMap
+    autoload :Explain
   end
 
   module Coders
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
diff --git a/activerecord/test/cases/explain_test.rb b/activerecord/test/cases/explain_test.rb
new file mode 100644
index 0000000000..d3eb9c2cb2
--- /dev/null
+++ b/activerecord/test/cases/explain_test.rb
@@ -0,0 +1,91 @@
+require 'cases/helper'
+require 'models/car'
+require 'active_support/core_ext/string/strip'
+
+if ActiveRecord::Base.connection.supports_explain?
+  class ExplainTest < ActiveRecord::TestCase
+    fixtures :cars
+
+    def base
+      ActiveRecord::Base
+    end
+
+    def connection
+      base.connection
+    end
+
+    def test_logging_query_plan
+      base.logger.expects(:warn).with do |value|
+        value.starts_with?('EXPLAIN for:')
+      end
+
+      with_threshold(0) do
+        Car.where(:name => 'honda').all
+      end
+    end
+
+    def test_collecting_sqls_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
+      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
+      end
+
+      assert_equal result, [honda]
+      assert_equal expected_sqls, sqls
+      assert_equal expected_binds, binds
+    end
+
+    def test_exec_explain_with_no_binds
+      sqls  = %w(foo bar)
+      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)
+    end
+
+    def test_exec_explain_with_binds
+      cols = [Object.new, Object.new]
+      cols[0].expects(:name).returns('wadus')
+      cols[1].expects(:name).returns('chaflan')
+
+      sqls  = %w(foo bar)
+      binds = [[[cols[0], 1]], [[cols[1], 2]]]
+
+      connection.stubs(:explain).returns("query plan foo\n", "query plan bar\n")
+      expected = <<-SQL.strip_heredoc
+        EXPLAIN for: #{sqls[0]} [["wadus", 1]]
+        query plan foo
+
+        EXPLAIN for: #{sqls[1]} [["chaflan", 2]]
+        query plan bar
+      SQL
+      assert_equal expected, base.exec_explain(sqls, binds)
+    end
+
+    def with_threshold(threshold)
+      current_threshold = base.auto_explain_threshold_in_seconds
+      base.auto_explain_threshold_in_seconds = threshold
+      yield
+    ensure
+      base.auto_explain_threshold_in_seconds = current_threshold
+    end
+  end
+end
diff --git a/railties/CHANGELOG.md b/railties/CHANGELOG.md
index d158fdd46f..a324486d6f 100644
--- a/railties/CHANGELOG.md
+++ b/railties/CHANGELOG.md
@@ -1,6 +1,11 @@
 ## Rails 3.2.0 (unreleased) ##
 
-*   Add DebugExceptions middleware which contains features extracted from ShowExceptions middleware *José Valim*
+*   New applications get a flag
+    `config.active_record.auto_explain_threshold_in_seconds` in the evironments
+    configuration files. With a value of 0.5 in development.rb, and commented
+    out in production.rb. No mention in test.rb. *fxn*
+
+*   Display mounted engine's routes in `rake routes`. *Piotr Sarnacki*
 
 *   Display mounted engine's routes in `rake routes` *Piotr Sarnacki*
 
diff --git a/railties/guides/code/getting_started/config/environments/development.rb b/railties/guides/code/getting_started/config/environments/development.rb
index 89932bf19b..d60a10568b 100644
--- a/railties/guides/code/getting_started/config/environments/development.rb
+++ b/railties/guides/code/getting_started/config/environments/development.rb
@@ -22,6 +22,13 @@ Blog::Application.configure do
   # Only use best-standards-support built into browsers
   config.action_dispatch.best_standards_support = :builtin
 
+  # Raise exception on mass assignment protection for ActiveRecord models
+  config.active_record.mass_assignment_sanitizer = :strict
+
+  # Log the query plan for queries taking more than this (works
+  # with SQLite, MySQL, and PostgreSQL)
+  config.active_record.auto_explain_threshold_in_seconds = 0.5
+
   # Do not compress assets
   config.assets.compress = false
 
diff --git a/railties/guides/code/getting_started/config/environments/production.rb b/railties/guides/code/getting_started/config/environments/production.rb
index dee8acfdfe..c9b2f41c39 100644
--- a/railties/guides/code/getting_started/config/environments/production.rb
+++ b/railties/guides/code/getting_started/config/environments/production.rb
@@ -60,4 +60,8 @@ Blog::Application.configure do
 
   # Send deprecation notices to registered listeners
   config.active_support.deprecation = :notify
+
+  # Log the query plan for queries taking more than this (works
+  # with SQLite, MySQL, and PostgreSQL)
+  # config.active_record.auto_explain_threshold_in_seconds = 0.5
 end
diff --git a/railties/guides/source/configuring.textile b/railties/guides/source/configuring.textile
index d91011c370..24bf9d863b 100644
--- a/railties/guides/source/configuring.textile
+++ b/railties/guides/source/configuring.textile
@@ -268,6 +268,8 @@ h4. Configuring Active Record
 
 * +config.active_record.identity_map+ controls whether the identity map is enabled, and is false by default.
 
+* +config.active_record.auto_explain_threshold_in_seconds+ configures the threshold for automatic EXPLAINs (+nil+ disables this feature). Queries taking more than those many seconds get their query plan logged. Default is 0.5 in development mode.
+
 The MySQL adapter adds one additional configuration option:
 
 * +ActiveRecord::ConnectionAdapters::MysqlAdapter.emulate_booleans+ controls whether Active Record will consider all +tinyint(1)+ columns in a MySQL database to be booleans and is true by default.
diff --git a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
index 47078e3af9..beaf941282 100644
--- a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
+++ b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
@@ -25,6 +25,10 @@
   <%- unless options.skip_active_record? -%>
   # Raise exception on mass assignment protection for ActiveRecord models
   config.active_record.mass_assignment_sanitizer = :strict
+
+  # Log the query plan for queries taking more than this (works
+  # with SQLite, MySQL, and PostgreSQL)
+  config.active_record.auto_explain_threshold_in_seconds = 0.5
   <%- end -%>
 
   # Do not compress assets
diff --git a/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt
index 50f2df3d35..40ec3fc644 100644
--- a/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt
+++ b/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt
@@ -60,4 +60,10 @@
 
   # Send deprecation notices to registered listeners
   config.active_support.deprecation = :notify
+
+  <%- unless options.skip_active_record? -%>
+  # Log the query plan for queries taking more than this (works
+  # with SQLite, MySQL, and PostgreSQL)
+  # config.active_record.auto_explain_threshold_in_seconds = 0.5
+  <%- end -%>
 end
diff --git a/railties/test/generators/app_generator_test.rb b/railties/test/generators/app_generator_test.rb
index 235c08e38e..41bb4d8b20 100644
--- a/railties/test/generators/app_generator_test.rb
+++ b/railties/test/generators/app_generator_test.rb
@@ -336,6 +336,15 @@ class AppGeneratorTest < Rails::Generators::TestCase
     end
   end
 
+  def test_generated_environments_file_for_auto_explain
+    run_generator [destination_root, "--skip-active-record"]
+    %w(development test production).each do |env|
+      assert_file "config/environments/#{env}.rb" do |file|
+        assert_no_match %r(auto_explain_threshold_in_seconds), file
+      end
+    end
+  end
+
 protected
 
   def action(*args, &block)