From 0306f82e0c3cda3aad1b45eb0c3a359c254b62cc Mon Sep 17 00:00:00 2001 From: Xavier Noria Date: Fri, 2 Dec 2011 04:32:18 -0800 Subject: implements automatic EXPLAIN logging for slow queries --- activerecord/lib/active_record.rb | 2 + activerecord/lib/active_record/base.rb | 10 ++- .../connection_adapters/abstract_adapter.rb | 6 ++ .../connection_adapters/abstract_mysql_adapter.rb | 74 -------------------- .../connection_adapters/mysql2_adapter.rb | 78 ++++++++++++++++++++++ .../connection_adapters/postgresql_adapter.rb | 9 ++- .../connection_adapters/sqlite_adapter.rb | 9 ++- activerecord/lib/active_record/explain.rb | 76 +++++++++++++++++++++ activerecord/lib/active_record/relation.rb | 45 ++++++++----- 9 files changed, 214 insertions(+), 95 deletions(-) create mode 100644 activerecord/lib/active_record/explain.rb (limited to 'activerecord/lib') 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] # > [#"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 -- cgit v1.2.3