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.

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