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