Rspec 2.7 total time is wrong

[Nerian]

Hi,

With the new release of RSpec 2.7 the total time calculation has been modified:

Provide more accurate run time by registering start time before code is loaded (David Chelimsky)
https://www.relishapp.com/rspec/rspec-core/docs/changelog

Check the Finished in *** seconds in the following code. It is calculated from the time guard was started. It doesn't reflect how much the actual test took to run.

$ guard
Guard is now watching at '/Users/Nerian/Projects/davinci'
Starting Spork for RSpec 
Using RSpec
Preloading Rails environment
Loading Spork.prefork block...
Spork is ready and listening on 8989!
Spork server for RSpec successfully started
Guard::RSpec is running, with RSpec 2!
Running all specs
Running tests with args ["--color", "--format", "progress", "--format", "Guard::RSpec::Formatter::NotificationRSpec", "--out", "/dev/null", "--require", "/Users/Nerian/.rvm/gems/ruby-1.9.3-rc1@davinci/gems/guard-rspec-0.5.0/lib/guard/rspec/formatters/notification_rspec.rb", "spec"]...
.................

Finished in 7.39 seconds
17 examples, 0 failures
Done.


Running all specs
Running tests with args ["--color", "--format", "progress", "--format", "Guard::RSpec::Formatter::NotificationRSpec", "--out", "/dev/null", "--require", "/Users/Nerian/.rvm/gems/ruby-1.9.3-rc1@davinci/gems/guard-rspec-0.5.0/lib/guard/rspec/formatters/notification_rspec.rb", "spec"]...
.................

Finished in 13.07 seconds
17 examples, 0 failures
Done.


Running all specs
Running tests with args ["--color", "--format", "progress", "--format", "Guard::RSpec::Formatter::NotificationRSpec", "--out", "/dev/null", "--require", "/Users/Nerian/.rvm/gems/ruby-1.9.3-rc1@davinci/gems/guard-rspec-0.5.0/lib/guard/rspec/formatters/notification_rspec.rb", "spec"]...
.................

Finished in 18.53 seconds
17 examples, 0 failures
Done.


Running all specs
Running tests with args ["--color", "--format", "progress", "--format", "Guard::RSpec::Formatter::NotificationRSpec", "--out", "/dev/null", "--require", "/Users/Nerian/.rvm/gems/ruby-1.9.3-rc1@davinci/gems/guard-rspec-0.5.0/lib/guard/rspec/formatters/notification_rspec.rb", "spec"]...
.................

Finished in 23.64 seconds
17 examples, 0 failures
Done.

[rymai]

That's because you're using Spork, and since the start time is now registered before code is loaded (in the prefork block of Spork) it's never refreshed... Don't know about a possible fix yet though.

Edit: Just made a comment on the commit that introduce this: rspec/rspec-core@fd04952#commitcomment-655593

[dchelimsky]

@rymai - thanks for bringing this to my attention. I need to give some thought to it, as I think it's important to include the time it takes rspec to load in the total time in a non-spork environment.

@Nerian - as a workaround until we get this sorted out, you can set $rspec_start_time ||= Time.now at the top of your Spork.each_run block. You'll lose the load time, but that's OK since it's not really part of each run anyway.

[rymai]

Thanks for the temporary workaround David!

I too think that's "important to include the time it takes rspec to load in the total time in a non-spork environment". :)

[rymai]

@Nerian, @dchelimsky - the issue has been reported in rspec-core.

[Nerian]

@dchelimsky - Thanks!

I did need to change it to:
$rspec_start_time = Time.now

[dchelimsky]

@Nerian - keep in mind that that is not intended to be a public API, and that it's possible this will break with the next release when we come up with a real solution. Should keep you going in the mean time.

[rymai]

Hi,

This issue is now fixed, thanks all!