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

On Mar 16, 6:31pm, Mattias A. [email protected] 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

This forum is not affiliated to the Ruby language, Ruby on Rails framework, nor any Ruby applications discussed here.

| Privacy Policy | Terms of Service | Remote Ruby Jobs