Rspec sometimes takes forever to finish on failed spec example(s)

[dicom]

I'm experiencing a somewhat annoying problem with rspec on a gem I'm developing on a Windows computer. Sometimes, when one or more spec examples fails, rspec takes forever to wrap up displaying the results of the spec run. It will report that execution of the examples was fairly quick (~10 seconds), but in reality, it takes several minutes before it manages to finish display the complete report in command prompt.

If no examples fails it always executes and prints the report quickly.
In many cases with failures it also executes quickly as normal.
In some cases though, it takes forever to wrap it up. When this occurs, it is deterministic, i.e. running the spec again (with that particular failure) always executes really slow.
I think I have never experienced this issue on a non-Windows computer.

The last time this occured for me (928 examples, 1 failure) I notice that it pauses (for a couple of minutes in this case) after having printed the lines:

1) RTKIT::ROI#distribution should return a DoseDistribution
  Failure/Error: distribution = @roi.distribution
  NoMethodError:

Then after a couple of minutes the actual error message is displayed (and the spec task finishes):

undefined method `sum' for #<RTKIT::RTDose:0x283c590>
  # ./lib/rtkit/roi.rb:225:in `distribution'
  # ./spec/rtkit/roi_spec.rb:392:in `block (3 levels) in <module:RTKIT>'

This happens no matter how I run the specs, e.g. bundle exec rake spec, rake spec, rspec, or rspec with --fail-fast option.

Have anyone else experienced this?
Is this a known issue with a known workaround? I have not been able to find any information on this issue.

Alternatively, if this is an unknown bug, is there something I can do to provide better debug information of what is going on?

System info:
OS: Windows XP SP3 32bit
Ruby: 1.9.3p125 (2012-02-16) [i386-mingw32]
Rubygems: 1.8.17
Rspec: 2.9.0

Regards,
Chris

[dchelimsky]

Yes this is a well known issue with Ruby on Windows (little RSpec can do about it):

https://www.google.com/search?aq=f&ix=acb&sourceid=chrome&ie=UTF-8&q=why+is+ruby+on+windows+so+slow

[luislavena]

@dchelimsky I think the user is referring to the time to print out the errors and not how long it takes to start and complete the tests itself.

@dicom can you confirm this? That the issue is not startup (from the time you hit enter to the time it completes) but from the time it finishes the test to the point it shows the backtrace?

[dicom]

@luislavena Yes, that is correct. The issue is not the time it takes to run the tests, but rather the time it takes to print the test results (backtrace). In cases where it takes many minutes to actually print the report, rspec will still report that it finished in only a few seconds, e.g.:

Finished in 11.73 seconds

[luislavena]

@dicom is this over a networked drive or something? Can you create a simple example that reproduces the issue? (like a repository to easy clone for example)

I don't have any project with RSpec 2 to try this out so can't comment further.

[dchelimsky]

@dicom, @luislavena I've reopened this issue. Unfortunately, I don't have a windows environment in which to debug it myself, so we're going to have to rely on active windows users like yourselves to debug this.

[luislavena]

@dchelimsky thanks, I'll work with @dicom to figure this out 😉

[dicom]

@luislavena it is not run over a network connection, it all runs from the local C drive.
Further, I have just tried it on another Windows computer, and I got the same behavior there as well. I will try to produce a simpler example which reproduces the issue for debug purposes, hopefully by tomorrow.
Thanks.

[dicom]

The plot thickens:
I tried this on my mac at home and guess what, the same issue was observed here too (OSX 10.6, Ruby 1.9.2p180). The spec suite that took an annoying couple of minutes to print the backtrace on Windows actually took a whopping 20+ minutes on my mac! (No idea how long it really took, as I eventually left the computer!) Sorry for mistakenly thinking this was an Windows-only issue.

I tried running the spec examples on Ruby 1.8.7 as well, but it wasn't a true 1:1 test, as I had to change some require_relative's to require to make it run. However, it did print and exit lightning fast on 1.8.7 (893 examples, 110 failures).

Stay tuned for news on a simplified example.

[dicom]

Ok, while trying to simplify the project code I finally got an idea of what is causing this:
The issue seems to happen when an example fails and there is a lot of data in memory.
I have constructed the following simple example which I believe demonstrates the same issue that I've been seeing in my project. This example results in an 'eternal' delay on printing the backtrace, and has been tested on OSX 10.6 with both Ruby 1.9.2 and 1.8.7.

Put the following in a file and run it with rspec:

class SomeClass
  def initialize
    @a = Array.new(100000, "just some random string")
  end
end

describe RSpec do
  it "should report a failure with NoMethodError and then (ideally) print the backtrace quickly" do
    h = Hash.new
    500.times {|i| h[i] = SomeClass.new}
    h.asdf.class.should eql ImaginaryClass
  end
end

You will observe that it quickly gets to this point:

chris$ rspec test_spec.rb 
F

Failures:

  1) RSpec should report a failure with NoMethodError and then (ideally) print the backtrace quickly
     Failure/Error: h.asdf.class.should eql ImaginaryClass
     NoMethodError:

The it stalls for a REALLY long time, until it will eventually print the rest:

       undefined method `asdf' for #<Hash:0x101179970>
     # ./test_spec.rb:11

Finished in 0.00191 seconds
1 example, 1 failure

Failed examples:

rspec ./test_spec.rb:8 # RSpec should report a failure with NoMethodError and then (ideally) print the backtrace quickly

I'm not knowledgable enough to tell if this is a limitation of the Ruby language, or indeed a bug that can be fixed, although I hope it is the latter, as this issue has been driving me insane at times! :(

Regards,
Chris

[luislavena]

@dicom this has nothing to do with RSpec then, the issue can be easily reproducible outside:

class SomeClass
  def initialize
    @a = Array.new(100000, "just some random string")
  end
end

h = Hash.new
500.times {|i| h[i] = SomeClass.new}
h.asdf

$ ruby t.rb 
t.rb:9:in `<main>'^C: undefined method `asdf' for #<Hash:0x0000010086b978> (NoMethodError)
^C

Hit Ctrl-C because was taking ages and was making my computer swap.

This is clearly the effect of the Garbage Collection having issues when allocating more than 1GB of data and trying to print out (allocating more memory).

[dchelimsky]

I'm going to go ahead and close this. Thanks to you both for helping to understand the problem.