implements automatic EXPLAIN logging for slow queries

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
 

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

activerecord/lib/active_record/base.rb

@@ -433,6 +433,11 @@ class Base
     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 @@ def generated_feature_methods
       #   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 @@ def populate_with_current_scope_attributes
     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.

activerecord/lib/active_record/connection_adapters/abstract_adapter.rb

@@ -142,6 +142,12 @@ def supports_index_sort_order?
         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.

activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb

@@ -225,80 +225,6 @@ def disable_referential_integrity(&block) #:nodoc:
 
       # 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

activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb

@@ -35,6 +35,10 @@ def initialize(connection, logger, connection_options, config)
         configure_connection
       end
 
+      def supports_explain?
+        true
+      end
+
       # HELPER METHODS ===========================================
 
       def each_hash(result) # :nodoc:
@@ -93,6 +97,80 @@ def reset!
 
       # 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

activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb

@@ -390,6 +390,11 @@ def supports_savepoints?
         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 @@ def disable_referential_integrity #:nodoc:
 
       # 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:

activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb

@@ -122,6 +122,11 @@ def supports_primary_key? #:nodoc:
         true
       end
 
+      # Returns true.
+      def supports_explain?
+        true
+      end
+
       def requires_reloading?
         true
       end
@@ -219,9 +224,9 @@ def type_cast(value, column) # :nodoc:
 
       # 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

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