Lighthouse has a new layout. Prefer the old one? Return to the old layout, and switch back any time from the link at the top of each page.

This project is archived and is in readonly mode.

Multiple database queries when chaining named scopes with rails 2.3.8 and ruby 1.9.2

#5410

I attached a sample project (testns) which demonstrates the following problem... In ruby 1.8.7, when chaining named scopes, only 1 query is made as it should. However, when using the same project under ruby 1.9.2, 2 queries are made for the same command. Here is the output for both ruby versions:

script/console output with ruby 1.8.7 (2009-06-12 patchlevel 174) and rails 2.3.8

>>ParentModel.first.test_models.high_priority.ordered SQL (0.2ms) SET NAMES 'utf8'
SQL (0.1ms) SET SQL_AUTO_IS_NULL=0
ParentModel Load (0.3ms) SELECT * FROM parent_models LIMIT 1
ParentModel Columns (1.0ms) SHOW FIELDS FROM parent_models

TestModel Load (0.3ms) SELECT * FROM test_models WHERE (test_models.parent_model_id = 1) AND ((priority > 5) AND (test_models.parent_model_id = 1)) ORDER BY name asc

TestModel Columns (0.9ms) SHOW FIELDS FROM test_models

[#<TestModel id: 11, name: "a11", priority: 11, created_at: "2010-08-19 15:20:23", updated_at: "2010-08-19 15:20:23", parent_model_id: 1>, #<TestModel id: 10, name: "test10", priority: 10, created_at: "2010-08-19 15:20:11", updated_at: "2010-08-19 15:20:11", parent_model_id: 1>, #<TestModel id: 6, name: "test6", priority: 6, created_at: "2010-08-19 15:19:49", updated_at: "2010-08-19 15:19:49", parent_model_id: 1>, #<TestModel id: 7, name: "test7", priority: 7, created_at: "2010-08-19 15:19:54", updated_at: "2010-08-19 15:19:54", parent_model_id: 1>, #<TestModel id: 8, name: "test8", priority: 8, created_at: "2010-08-19 15:20:00", updated_at: "2010-08-19 15:20:00", parent_model_id: 1>, #<TestModel id: 9, name: "test9", priority: 9, created_at: "2010-08-19 15:20:06", updated_at: "2010-08-19 15:20:06", parent_model_id: 1>]

script/console output with ruby-1.9.2-p0 and rails 2.3.8 (same output seen with ruby 1.9.2 rc2...not new to p0)

>>ParentModel.first.test_models.high_priority.ordered SQL (0.1ms) SET NAMES 'utf8'
SQL (0.1ms) SET SQL_AUTO_IS_NULL=0
ParentModel Load (0.2ms) SELECT * FROM parent_models LIMIT 1
ParentModel Columns (1.1ms) SHOW FIELDS FROM parent_models

TestModel Load (0.3ms) SELECT * FROM test_models WHERE (test_models.parent_model_id = 1)

TestModel Load (0.2ms) SELECT * FROM test_models WHERE (test_models.parent_model_id = 1) AND ((priority > 5) AND (test_models.parent_model_id = 1)) ORDER BY name asc

TestModel Columns (0.9ms) SHOW FIELDS FROM test_models

[#<TestModel id: 11, name: "a11", priority: 11, created_at: "2010-08-19 15:20:23", updated_at: "2010-08-19 15:20:23", parent_model_id: 1>, #<TestModel id: 10, name: "test10", priority: 10, created_at: "2010-08-19 15:20:11", updated_at: "2010-08-19 15:20:11", parent_model_id: 1>, #<TestModel id: 6, name: "test6", priority: 6, created_at: "2010-08-19 15:19:49", updated_at: "2010-08-19 15:19:49", parent_model_id: 1>, #<TestModel id: 7, name: "test7", priority: 7, created_at: "2010-08-19 15:19:54", updated_at: "2010-08-19 15:19:54", parent_model_id: 1>, #<TestModel id: 8, name: "test8", priority: 8, created_at: "2010-08-19 15:20:00", updated_at: "2010-08-19 15:20:00", parent_model_id: 1>, #<TestModel id: 9, name: "test9", priority: 9, created_at: "2010-08-19 15:20:06", updated_at: "2010-08-19 15:20:06", parent_model_id: 1>]

Reported by Jeremy Suriel · August 19th, 2010 @ 05:10 PM

State: committed
Milestone: none
Assigned to: Aaron Patterson Aaron Patterson
Importance: Low

Activity

  1. Stephen Blackstone
    Stephen Blackstone

    Same Problem here.. It also works fine under 1.9.1p243 but not 1.9.2...

    I'm using Rails 2.3.9

    Group
    has_many :topics, :as => :discussable (via a module)

    Topic
    belongs_to :discussable, :polymorphic => true named_scope :unhidden, { :conditions => ['hidden = ?', false] }

    Under rails 1.9.2 without the named_scope this works properly:

    reload! ; Group.find(56).topics.size

    Reloading...
    ...snip show tables etc... Group Load (12.8ms) SELECT FROM groups WHERE (groups.id = 56) Topic Columns (13.6ms) SHOW FIELDS FROM topics SQL (81.7ms) SELECT count() AS count_all FROM topics WHERE (topics.discussable_id = 56 AND topics.discussable_type = 'Group')

    However with the named scope in there:

    reload! ; Group.find(56).topics.unhidden.size

    Group Load (14.3ms) SELECT FROM groups WHERE (groups.id = 56) Topic Load (40.1ms) SELECT FROM topics WHERE (topics.discussable_id = 56 AND topics.discussable_type = 'Group') Topic Columns (13.5ms) SHOW FIELDS FROM topics SQL (11.8ms) SELECT count(*) AS count_all FROM topics WHERE (((hidden = 0) AND (topics.discussable_id = 56 AND topics.discussable_type = 'Group')) AND (topics.discussable_id = 56 AND topics.discussable_type = 'Group'))

    So the problem is under the seond one, it selects all the topics and then
    does select count(*).

    Under rails 1.9.1p243 this worked correctly in both cases.

    October 19th, 2010 @ 09:56 PM

  2. Stephen Blackstone
    Stephen Blackstone

    The problem appears to be when on line 146 in association proxy send gets called with "current_scoped_methods". This causes proxy_respond_to to call respond_to? which causes a method missing which causes a load_target to be called by the association collection.

    /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/base.rb:666:in find_by_sql' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/base.rb:1589:infind_every' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/base.rb:619:in find' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:60:infind' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:425:in find_target' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:367:inload_target' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_proxy.rb:219:in method_missing' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:396:inmethod_missing' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:343:in respond_to?' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:343:inproxy_respond_to?' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_proxy.rb:146:in send' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/named_scope.rb:124:ininitialize' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/named_scope.rb:90:in new' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/named_scope.rb:90:inblock in named_scope' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:399:in call' /usr/local/ruby19/lib/ruby/gems/1.9.1/gems/activerecord-2.3.9/lib/active_record/associations/association_collection.rb:399:inmethod_missing'

    October 20th, 2010 @ 06:06 PM

  3. Stephen Blackstone
    Stephen Blackstone

    Sorry about the formatting above =)

    The problem is that in association_collection, method missing is getting called with respond_to somewhere is calling respond_to_missing which is causing a new method_missing on the respond_to_missing which triggers the code path which causes the underlying collection to load.

    This doesn't solve the underlying issue (dealing with the new calls to respond_to_missing?) but does act as a workaround:

    --- association_collection.rb 2010-10-20 13:22:58.629947001 -0400 +++ /root/association_collection.rb 2010-10-20 13:22:54.509947004 -0400 @@ -390,7 +390,7 @@

             if block_given?
               super { |*block_args| yield(*block_args) }
             else
    
    •        super
      
    •        super unless method.to_s == "respond_to_missing?"
           end
         elsif @reflection.klass.scopes.include?(method)
           @reflection.klass.scopes[method].call(self, *args)
      

    October 20th, 2010 @ 06:31 PM

  4. Jeremy Suriel
    Jeremy Suriel

    Stephen, thanks for the workaround. I created the attached rails initializer file and the problem seems to be fixed. I am still concerned however about the new calls to repsond_to_missing as you mentioned, and if this workaround causes issues elsewhere...

    October 20th, 2010 @ 07:31 PM

  5. Stephen Blackstone
    Stephen Blackstone
    • Tag changed from rails 2.3.8, named_scope, ruby-1.9.2 to rails 2.3.8, named_scope, patch, ruby-1.9.2

    Jeremy -

    Most of the places where rails is using method_missing in this morass is guarded by things like:
    if @target.respond_to?(method) || (!@reflection.klass.respond_to?(method) && Class.respond_to?(method)

    The only reason this slips through is because responds_to_missing? became a part of the underlying ruby class..

    Attached is a proper patch off git. This same fix should also backported into 2.3.9..

    October 20th, 2010 @ 07:48 PM

  6. Jeremy Suriel
    Jeremy Suriel

    Got it, thanks for the info. Any idea when/if this patch will be applied to 2.3?

    October 20th, 2010 @ 07:56 PM

  7. Stephen Blackstone
    Stephen Blackstone
    • Assigned user set to Ryan Bigg

    October 22nd, 2010 @ 06:13 AM

  8. Ken Collins
    Ken Collins

    Can anyone run the tests for ActiveRecord under 1.9.2? I can not, and created ticket 5887. I verified that this patch does somewhat speed up my app's testing under 1.9.2, but it's still slow and I would like to profile by running the tests and possibly find a few more places that need 1.9.2 help.

    October 29th, 2010 @ 03:12 PM

  9. Ken Collins
  10. Jeff Kreeftmeijer
    Jeff Kreeftmeijer
    • Tag cleared.
    • Importance changed from to Low

    Automatic cleanup of spam.

    November 1st, 2010 @ 05:03 PM

  11. Stephen Blackstone
    Stephen Blackstone
    • Tag set to patch
    • Assigned user changed from Ryan Bigg to Jeff Kreeftmeijer

    Here's an updated patch that fixes the underlying problem rather than just covering it up.

    AssociationProxy does this:
    instance_methods.each { |m| undef_method m unless m.to_s =~ /^(?:nil\?|send|object_id|to_a)$|^_|proxy/ }

    Because of this, in Ruby 1.9.2 it will wipe out the default respond_to_missing?

    Since the default is gone, it then sends the method call to method_missing

    The patch just adds an exception to the regular exception so it preserves respond_to_missing if it exists. This should be fully compatible with Ruby 1.8.6 since the method doesn't exist in the first place. It should be trivial to also add the same line to the 2.3.10 codebase to fix the same problem.. (patch is off of git)

    November 3rd, 2010 @ 06:23 PM

  12. Jeff Kreeftmeijer
    Jeff Kreeftmeijer
    • Assigned user changed from Jeff Kreeftmeijer to Aaron Patterson

    November 3rd, 2010 @ 07:12 PM

  13. Stephen Blackstone
  14. Aaron Patterson
    Aaron Patterson
    • State changed from new to committed

    Applied. Thanks!

    November 4th, 2010 @ 10:05 PM