aboutsummaryrefslogtreecommitdiffstats
path: root/activerecord/lib/active_record
diff options
context:
space:
mode:
authorXavier Noria <fxn@hashref.com>2011-12-02 04:32:18 -0800
committerXavier Noria <fxn@hashref.com>2011-12-02 04:35:43 -0800
commit0306f82e0c3cda3aad1b45eb0c3a359c254b62cc (patch)
tree08ddebf4733e3b3c2b24d4ee1db8313c4a447f71 /activerecord/lib/active_record
parent4d20de8a50d889a09e6f5642984775fe796ca943 (diff)
downloadrails-0306f82e0c3cda3aad1b45eb0c3a359c254b62cc.tar.gz
rails-0306f82e0c3cda3aad1b45eb0c3a359c254b62cc.tar.bz2
rails-0306f82e0c3cda3aad1b45eb0c3a359c254b62cc.zip
implements automatic EXPLAIN logging for slow queries
Diffstat (limited to 'activerecord/lib/active_record')
-rw-r--r--activerecord/lib/active_record/base.rb10
-rw-r--r--activerecord/lib/active_record/connection_adapters/abstract_adapter.rb6
-rw-r--r--activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb74
-rw-r--r--activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb78
-rw-r--r--activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb9
-rw-r--r--activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb9
-rw-r--r--activerecord/lib/active_record/explain.rb76
-rw-r--r--activerecord/lib/active_record/relation.rb45
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