mirror of
https://github.com/rails/rails.git
synced 2022-11-09 12:12:34 -05:00
cfeac38e2b
This commit vastly reduces the impact of auto explain logging when enabled, while keeping a negligible cost when disabled. The first implementation was based on the idea of subscribing to "sql.active_record" when needed, and unsubscribing once done. This is the idea behind AR::Relation#explain. Subscribe, collect, unsubscribe. But with the current implementation of notifications unsubscribing is costly, because it wipes an internal cache and that puts a penalty on the next event. So we are switching to an approach where a long-running subscriber is listening. Instead of collecting the queries with a closure in a dedicated subscriber, now we setup a thread local. If the feature is disabled by setting the threshold to nil, the subscriber will call a method that does nothing. That's totally cheap.
101 lines
2.7 KiB
Ruby
101 lines
2.7 KiB
Ruby
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 |message|
|
|
message.starts_with?('EXPLAIN for:')
|
|
end
|
|
|
|
with_threshold(0) do
|
|
Car.where(:name => 'honda').all
|
|
end
|
|
end
|
|
|
|
def test_collect_queries_for_explain
|
|
base.auto_explain_threshold_in_seconds = nil
|
|
queries = Thread.current[:available_queries_for_explain] = []
|
|
|
|
with_threshold(0) do
|
|
Car.where(:name => 'honda').all
|
|
end
|
|
|
|
sql, binds = queries[0]
|
|
assert_match "SELECT", sql
|
|
assert_match "honda", sql
|
|
assert_equal [], binds
|
|
ensure
|
|
Thread.current[:available_queries_for_explain] = nil
|
|
end
|
|
|
|
def test_collecting_queries_for_explain
|
|
result, queries = ActiveRecord::Base.collecting_queries_for_explain do
|
|
Car.where(:name => 'honda').all
|
|
end
|
|
|
|
sql, binds = queries[0]
|
|
assert_match "SELECT", sql
|
|
assert_match "honda", sql
|
|
assert_equal [], binds
|
|
assert_equal [cars(:honda)], result
|
|
end
|
|
|
|
def test_exec_explain_with_no_binds
|
|
sqls = %w(foo bar)
|
|
binds = [[], []]
|
|
queries = sqls.zip(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(queries)
|
|
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]]]
|
|
queries = sqls.zip(binds)
|
|
|
|
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(queries)
|
|
end
|
|
|
|
def test_silence_auto_explain
|
|
base.expects(:collecting_sqls_for_explain).never
|
|
base.logger.expects(:warn).never
|
|
base.silence_auto_explain do
|
|
with_threshold(0) { Car.all }
|
|
end
|
|
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
|