Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

Don't run explain on slow queries for database adapters that don't support it #6197

Merged
merged 1 commit into from

9 participants

@blakesmith

When using the activerecord-jdbcmysql connection adapter, I received this exception after a slow query fired:


NoMethodError: undefined method `explain' for #<ActiveRecord::ConnectionAdapters::MysqlAdapter:0x1c92233b>
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/explain.rb:65:in `exec_explain'
    from org/jruby/RubyKernel.java:1787:in `tap'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/explain.rb:59:in `exec_explain'
    from org/jruby/RubyArray.java:2339:in `collect'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/explain.rb:58:in `exec_explain'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/explain.rb:34:in `logging_query_plan'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/relation.rb:159:in `to_a'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/relation/finder_methods.rb:377:in `find_first'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/relation/finder_methods.rb:122:in `first'
    from org/jruby/RubyBasicObject.java:1698:in `__send__'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/activerecord-3.2.3/lib/active_record/querying.rb:5:in `first'
    from (irb):1:in `evaluate'
    from org/jruby/RubyKernel.java:1088:in `eval'
    from org/jruby/RubyKernel.java:1410:in `loop'
    from org/jruby/RubyKernel.java:1197:in `catch'
    from org/jruby/RubyKernel.java:1197:in `catch'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/railties-3.2.3/lib/rails/commands/console.rb:47:in `start'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/railties-3.2.3/lib/rails/commands/console.rb:8:in `start'
    from /Users/blake/.rvm/gems/jruby-1.6.7-d19@myapp/gems/railties-3.2.3/lib/rails/commands.rb:41:in `(root)'
    from org/jruby/RubyKernel.java:1042:in `require'
    from script/rails:6:in `(root)'jruby-1.6.7-d19 :002 > 

Digging a little deeper, it seems that only mysql2, postgres and sqlite3 support explain on the connection adapter. This change prevents the slow query explain from running if the connection adapter does not support it. Ideally, the test wouldn't stub out 'supports_explain?' on a connection that does indeed support it, but we don't yet have any tests that run end-to-end against a jruby runtime and use the jdbc drivers.

Feedback appreciated!

Blake

@blakesmith

Thoughts, @fxn?

@blakesmith

For now, I've commented out the query explain threshold in my app, but this exception is a bad experience. Does anyone else have any input on this patch?

@steveklabnik
Collaborator
@fxn fxn was assigned
@tenderlove
Owner

Is it possible to use a respond_to? rather than adding another predicate method to the connection adapters? I haven't looked very closely at the explain implementation, so I'm not sure if it's possible.

@blakesmith

It seems like the only other dependencies on the connection adapter's supports_explain? are in the tests - so this predicate seems to have limited value. I like your suggestion to remove supoorts_explain? altogether - and use respond_to? instead. Pull request forthcoming.

@fxn
Owner

As of today, if the user sets auto_explain_threshold_in_seconds to some value, then he is telling Active Record that he wants auto explains.

When I wrote this feature I thought perhaps that was enough interface. Do you want automatic explains? set a threshold. You don't want them? do not tell Active Record to monitor queries.

But I see your point and perhaps practice is telling that contract is not enough. The application could perhaps warn: "auto_explain_threshold_in_seconds is set but will be ignored because your adapter does not support this feature. Please unset the configuration to avoid this warning." and then in any case be robust to that and do not break. So in that sense I am positive about doing something about this.

At application generation time unfortunately we can't tell because we have no adapter at that moment to ask and we generate unconditionally (unless Active Record itself is skipped via its flag).

So :+1: to check supports_explain?.

I am strongly :-1: on basing this on respond_to? because there are many predicates inherited from the abstract adapter to be overriden by adapters in the same fashion. See supports_count_distinct?, supports_migrations?, supports_savepoints? and a ton others. supports_explain? was implemented that way to follow this already existing pattern.

@steveklabnik
Collaborator

rails new automatically sets auto_explain_threshold_in_seconds in new apps, though, right?

@fxn
Owner

Oh, by the way. In addition to follow the pattern, I prefer the predicate because it is semantically better for my taste.

This is not "check if it supports explain to immediately call the explain method", I want to know if the adapter supports this feature in the abstract, regardless of the interface it should implement. What methods I am going to call down the stack are not important if I am at the top level checking whether I should do explain stuff at all.

@fxn
Owner

@steveklabnik yeah, see the 4th paragraph of my comment for the reason.

@mikelikesbikes

@steveklabnik: Yes, new rails apps come with auto_explain_threshold_in_seconds set, this is what caused the original issue when the adapter didn't support explain.

@fxn thanks for the background on the other predicates used in the adapter code. It seems like the best course of action is to stick with the convention already in use (using predicate methods). Perhaps it's worth discussing the use of the predicates vs. respond_to? in a separate issue (or later refactoring).

I also agree, that if auto_explain_threshold_in_seconds is set in the config and the adapter does not support explain, then Rails should warn the user about the mismatch, and skip the explain.

Seems like the first commit c976341, plus a new commit to warn about the mismatch would be enough to get past the bug presented here.

@steveklabnik
Collaborator

@fxn right, what I meant to imply was that while I agree with your original 'contract,' that muddies the issue, basically.

@fxn
Owner

@mikelikesbikes sounds good.

@steveklabnik yes, application generation is imperfect there. I didn't want to hard-code a list of strings, because the adapters my change anytime and it didn't seem a perfect solution either. Solution to the dilemma: embrace imperfection :).

And even if you could avoid the generation depending on the adapter in a good way, this pull request would still make sense to me because it is not uncommon that you generate whatever to bootstrap, or you just forget to use the database flag of the generator, and later you edit config/database.yml to change the adapter.

@fxn
Owner

Ping :).

@carlosantoniodasilva

@tenderlove @fxn what's the verdict here? respond_to?, supports_explain? :smile:

@tenderlove
Owner

Sorry! I agree with @fxn, use supports_explain? :-)

@carlosantoniodasilva

@tenderlove alright, thanks! :)

@mikelikesbikes hey, could you move this forward with supports_explain? and the warn, as you commented, so we can get it merged? If you have any issue, please let us know, thanks.

@fxn
Owner

@carlosantoniodasilva thanks for the ping :).

@fxn
Owner

@mikelikesbikes hey, any news on this patch?

@amaia

The creator of the pull request was @blakesmith it might be better to ping him

@blakesmith

Cool, thanks for the feeback @fxn, and sorry for the slow response. I'll revert to using suports_explain?

In terms of warning on boot, can you provide guidance on where that should go? It looks like it should happen when loading active_record, which leads me to believe it should happen in activerecord/lib/active_record/railtie.rb

Does something like this make sense?

diff --git a/activerecord/lib/active_record/railtie.rb b/activerecord/lib/active_record/railtie.rb
index ecf8547..1f3b669 100644
--- a/activerecord/lib/active_record/railtie.rb
+++ b/activerecord/lib/active_record/railtie.rb
@@ -109,6 +109,13 @@ module ActiveRecord
       end
     end

+    initializer "active_record.validate_explain_support" do |app|
+      if app.config.active_record[:auto_explain_threshold_in_seconds] &&
+        !ActiveRecord::Model.connection.supports_explain?
+        warn "auto_explain_threshold_in_seconds is set but will be ignored because your adapter does not support this feature. Please unset the configuration to avoid this warning."
+      end
+    end
+
     # Expose database runtime to controller for logging.
     initializer "active_record.log_runtime" do |app|
       require "active_record/railties/controller_runtime"
@steveklabnik
Collaborator

@fxn any thoughts for @blakesmith ?

@rafaelfranca

@blakesmith make sense to me. Now you will have to change to ActiveRecord::Base since ActiveRecord::Model was removed. Lets move this ahead to get it merged before 4.0 please

@blakesmith

Thanks for the feedback @rafaelfranca. I've created a new branch with the suggestions and squashed into a single commit.

SHA1: 77a075b

  1. Use supports_explain? to detect connection adapter capabilities
  2. Warning if auto_explain_threshold_in_seconds is set in the config, but the adapter does not support it
  3. Updated to use ActiveRecord::Base instead of ActiveRecord::Model
  4. Removed the all finder call and replaced it with to_a in the test
@fxn
Owner

@blakesmith the PR no longer merges... could you please rebase?

@rafaelfranca

@blakesmith you forgot to update the pull request. The supports_explain? is not in the code.

@blakesmith

@rafaelfranca @fxn Ok, I updated this branch to make it easier for you guys to merge. This fix should merge cleanly now.

Thanks for the help.

@fxn fxn merged commit 296412f into rails:master
@carlosantoniodasilva carlosantoniodasilva commented on the diff
activerecord/test/cases/explain_test.rb
@@ -108,6 +108,16 @@ def test_exec_explain_with_binds
assert_equal expected, base.exec_explain(queries)
end
+ def test_unsupported_connection_adapter
+ connection.stubs(:supports_explain?).returns(false)
+
+ base.logger.expects(:warn).never

I don't think the warn method triggered there is on the logger, is it?

@carlosantoniodasilva The other tests make similar assertions (See here ).

You should be able to see the test fail if you remove the supports_explain? guard. Are you seeing something wrong?

Ok, I didn't notice the other tests. I can't take a look right now to see if I missed anything, I'll report back later. Thanks @blakesmith.

@blakesmith sorry about that, when glancing at the code really quickly I thought you were testing the initializer (which called warn), but it has nothing to do with it. Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@superchris

What are the chances this could make it into a point release of 3.2 as well?

@carlosantoniodasilva

It seems fine to backport, but @fxn can confirm that.

@fxn
Owner

:+1:

@blakesmith blakesmith deleted the blakesmith:connection_adapters_without_explain_support branch
@rafaelfranca

This warning is making some task like rake db:test:load to try to connect to development database. I think we should removed it or change this code to try to connect to the right database.

@rafaelfranca
FATAL:  database "my_project_development" does not exist
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/postgresql_adapter.rb:1216:in `initialize'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/postgresql_adapter.rb:1216:in `new'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/postgresql_adapter.rb:1216:in `connect'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/postgresql_adapter.rb:324:in `initialize'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/postgresql_adapter.rb:28:in `new'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/postgresql_adapter.rb:28:in `postgresql_connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:315:in `new_connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:325:in `checkout_new_connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:247:in `block (2 levels) in checkout'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:242:in `loop'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:242:in `block in checkout'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:239:in `checkout'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:102:in `block in connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:101:in `connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:410:in `retrieve_connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_specification.rb:171:in `retrieve_connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_specification.rb:145:in `connection'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/railtie.rb:88:in `block in <class:Railtie>'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/initializable.rb:30:in `instance_exec'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/initializable.rb:30:in `run'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/initializable.rb:55:in `block in run_initializers'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/initializable.rb:54:in `each'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/initializable.rb:54:in `run_initializers'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/application.rb:136:in `initialize!'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/railtie/configurable.rb:30:in `method_missing'
/home/rafaelfranca/src/my_project/config/environment.rb:5:in `<top (required)>'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `require'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `block in require'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:236:in `load_dependency'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `require'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/application.rb:103:in `require_environment!'
/home/rafaelfranca/src/my_project/vendor/ruby/1.9.1/gems/railties-3.2.13/lib/rails/application.rb:297:in `block (2 levels) in initialize_tasks'
Tasks: TOP => db:test:load => db:test:purge => environment
@jrafanie jrafanie referenced this pull request from a commit in ManageIQ/rails
@jrafanie jrafanie Revert "Merge pull request #6197 from blakesmith/connection_adapters_…
…without_explain_support"

This reverts commit 29d564a.

This Rails upstream commit, added after 3.2.12 and included in 3.2.13, mistakenly opens a database connection to check for auto explain support.
This causes issues if you use threads as each will make a database connection for any queries, even cached ones.

It turns out that the upstream Rails 4-0-stable branch has this issue fixed as they removed the auto explain feature entirely: rails#9400
That pull references this issue, rails#9385, where a database connection was required during assets precompiling following the commit we are reverting.
f3621ad
@wkj wkj referenced this pull request from a commit
@rafaelfranca rafaelfranca Removing explain support warning from the Railtie
This is causing a regression since the Active Record Railtie is trying to
connect to the development database in the application boot.

See #6197 (comment)
e06b4fa
@rowland39 rowland39 referenced this pull request from a commit
Commit has since been removed from the repository and is no longer available.
@jrafanie jrafanie referenced this pull request from a commit in ManageIQ/rails
@jrafanie jrafanie Revert "Merge pull request #6197 from blakesmith/connection_adapters_…
…without_explain_support"

This reverts commit 29d564a.

This Rails upstream commit, added after 3.2.12 and included in 3.2.13, mistakenly opens a database connection to check for auto explain support.
This causes issues if you use threads as each will make a database connection for any queries, even cached ones.

It turns out that the upstream Rails 4-0-stable branch has this issue fixed as they removed the auto explain feature entirely: rails#9400
That pull references this issue, rails#9385, where a database connection was required during assets precompiling following the commit we are reverting.
be1484c
@jrafanie jrafanie referenced this pull request from a commit in ManageIQ/rails
@jrafanie jrafanie Revert "Merge pull request #6197 from blakesmith/connection_adapters_…
…without_explain_support"

This reverts commit 29d564a.

This Rails upstream commit, added after 3.2.12 and included in 3.2.13, mistakenly opens a database connection to check for auto explain support.
This causes issues if you use threads as each will make a database connection for any queries, even cached ones.

It turns out that the upstream Rails 4-0-stable branch has this issue fixed as they removed the auto explain feature entirely: rails#9400
That pull references this issue, rails#9385, where a database connection was required during assets precompiling following the commit we are reverting.
5655057
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
This page is out of date. Refresh to see the latest.
View
13 activerecord/lib/active_record/explain.rb
@@ -6,11 +6,12 @@ def self.extended(base)
base.mattr_accessor :auto_explain_threshold_in_seconds, instance_accessor: false
end
- # 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.
+ # If the database adapter supports explain and 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.
+
#
# The available_queries_for_explain thread variable collects the queries
# to be explained. If the value is nil, it means queries are not being
@@ -21,7 +22,7 @@ def logging_query_plan # :nodoc:
threshold = auto_explain_threshold_in_seconds
current = Thread.current
- if threshold && current[:available_queries_for_explain].nil?
+ if connection.supports_explain? && threshold && current[:available_queries_for_explain].nil?
begin
queries = current[:available_queries_for_explain] = []
start = Time.now
View
7 activerecord/lib/active_record/railtie.rb
@@ -136,6 +136,13 @@ class Railtie < Rails::Railtie # :nodoc:
end
end
+ initializer "active_record.validate_explain_support" do |app|
+ if app.config.active_record[:auto_explain_threshold_in_seconds] &&
+ !ActiveRecord::Base.connection.supports_explain?
+ warn "auto_explain_threshold_in_seconds is set but will be ignored because your adapter does not support this feature. Please unset the configuration to avoid this warning."
+ end
+ end
+
# Expose database runtime to controller for logging.
initializer "active_record.log_runtime" do |app|
require "active_record/railties/controller_runtime"
View
10 activerecord/test/cases/explain_test.rb
@@ -108,6 +108,16 @@ def test_exec_explain_with_binds
assert_equal expected, base.exec_explain(queries)
end
+ def test_unsupported_connection_adapter
+ connection.stubs(:supports_explain?).returns(false)
+
+ base.logger.expects(:warn).never

I don't think the warn method triggered there is on the logger, is it?

@carlosantoniodasilva The other tests make similar assertions (See here ).

You should be able to see the test fail if you remove the supports_explain? guard. Are you seeing something wrong?

Ok, I didn't notice the other tests. I can't take a look right now to see if I missed anything, I'll report back later. Thanks @blakesmith.

@blakesmith sorry about that, when glancing at the code really quickly I thought you were testing the initializer (which called warn), but it has nothing to do with it. Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
+
+ with_threshold(0) do
+ Car.where(:name => 'honda').to_a
+ end
+ end
+
def test_silence_auto_explain
base.expects(:collecting_sqls_for_explain).never
base.logger.expects(:warn).never
Something went wrong with that request. Please try again.