Rails - Mar 2011 - Linear performance degradation with Active Record and NoMethodError

Hello!

While upgrading our application to rails 3 I ran into some strange 
behavior with our test suite. Printing the test results seemed to take 
too long, and got stuck for several seconds halfway through printing the 
test report.

This only occurred if I combined some of my tests in the same test 
cycle, but only with specific combinations.

This lead me to investigating and I managed to narrow it down to this: 
If I create a large number (say 10000) of Active Record objects, then 
calling to_s on a NoMethodError takes approximately 2 seconds. The time 
grows linearly with the number of objects I create.

The interesting part is that this happens even if I create the objects 
in one test and call the undefined method in a different file.

I can replicate this in all released versions rails3 using the test case 
below. I''ve tested it using both ruby 1.8.7 and 1.9.2. This is also a 
new behavior in rails 3 and I cannot replicate it with rails 2.3.11.

What I can see with ruby-debug it''s caused by to_s calling inspect on 
each Active Record object created in the earlier test. This seems 
unnecessary since it''s not actually included in the final error
message.

Before I dig deeper, is this expected and known behavior or am I 
actually looking at a bug?

The following is a test case which shows this behavior.

================# $ cat functional/foo_test.rb
require ''test_helper''

class FooTest < ActionController::TestCase
   test "test a" do
     p "Start of create"
     (1..10000).each do |i|
       Bar.create!
     end
     p "Done with create"
   end


#  def blahonga()
#  end

   test "test b" do
     start = Time.now
     p "Start of test"
     begin
       blahonga()
     rescue Exception => e
       p "Caught exception at time #{((Time.now - start)*1000000).to_i}
us"
       msg = e.to_s
       p "ERROR #{msg} at time #{((Time.now - start)*1000000).to_i}
us"
     end
     p "Done with exception handler at time #{((Time.now - 
start)*1000000).to_i} us"
     p "Done with test"
   end
end
================
Regards
/mattiasa

-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.

On Mar 16, 6:31 pm, Mattias Amnefelt
<matti...-7MGv3I4iy7c@public.gmane.org> wrote:
> I can replicate this in all released versions rails3 using the test case
> below. I''ve tested it using both ruby 1.8.7 and 1.9.2. This is
also a
> new behavior in rails 3 and I cannot replicate it with rails 2.3.11.
>
> What I can see with ruby-debug it''s caused by to_s calling inspect
on
> each Active Record object created in the earlier test. This seems
> unnecessary since it''s not actually included in the final error
message.
>
That is very curious. The slow part seems to be calling inspect on the
testcase object, which seems to go through a bunch of routes related
stuff, although I don''t understand how or why that matters.

Fred
> Before I dig deeper, is this expected and known behavior or am I
> actually looking at a bug?
>
> The following is a test case which shows this behavior.
>
> ================> # $ cat functional/foo_test.rb
> require ''test_helper''
>
> class FooTest < ActionController::TestCase
>    test "test a" do
>      p "Start of create"
>      (1..10000).each do |i|
>        Bar.create!
>      end
>      p "Done with create"
>    end
>
> #  def blahonga()
> #  end
>
>    test "test b" do
>      start = Time.now
>      p "Start of test"
>      begin
>        blahonga()
>      rescue Exception => e
>        p "Caught exception at time #{((Time.now -
start)*1000000).to_i} us"
>        msg = e.to_s
>        p "ERROR #{msg} at time #{((Time.now - start)*1000000).to_i}
us"
>      end
>      p "Done with exception handler at time #{((Time.now -
> start)*1000000).to_i} us"
>      p "Done with test"
>    end
> end
> ================>
> Regards
> /mattiasa
-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe@googlegroups.com.
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.