jonleighton/spring-commands-rspec

Load time incorrect with Spring

nilbus opened this issue · 17 comments

nilbus commented

Standard practice now with Rails 4 seems to be to use Spring with spring-commands-rspec to generate bin/rspec. In rspec-core, because @load_time gets set in Reporter#start before Spring forks the rails process, the load time only gets set once, when the Spring server first starts. Every time I run my specs with bin/rspec, I get output like this:

Finished in 0.01662 seconds (files took 85 minutes 45 seconds to load)
12 examples, 0 failures, 3 pending

It was really just 85 minutes ago that Spring started.

When running rspec directly (not using the binstub provided by this gem), I do not have this issue.

I originally brought up the issue rspec/rspec-core#1574 with the rspec-core team, and we agreed that this would be better addressed by the launcher. @myronmarston pointed out that rspec exposes an attribute that alternate runners can set to the current time when they begin the setup for the next run.

I think this gem probably would be the most appropriate place to address this issue, but it also seems that the API provided by Spring::Commands is somewhat limited and may possibly not support what we need to do. You certainly would know better than me though. What are your thoughts?

jonleighton commented

Yep, I think we could/should handle this in spring-commands-rspec

merhard commented

I just added RSpec.configuration.start_time = Time.now to the binstub. Now my bin/rspec file looks like:

#!/usr/bin/env ruby
begin
  load File.expand_path("../spring", __FILE__)
rescue LoadError
end
require 'bundler/setup'
RSpec.configuration.start_time = Time.now
load Gem.bin_path('rspec-core', 'rspec')

and output after running the specs looks like:

Finished in 0.63245 seconds (files took 0.34743 seconds to load)
5 examples, 0 failures

At least as a temporary fix until the gem addresses it.

nilbus commented

👍

zorab47 commented

@merhard thanks, that's a helpful and easy temporary fix.

dankohn commented

Thanks, this fixed my issue. Anyone want to offer a pull request to replace the binstub on install?

nilbus commented

A permanent fix is not straightforward. Spring generates the binstub by filling in the blanks with values provided by this gem. In other words, there's no direct way to modify the binstub in the way suggested. I see a few options.

  1. Modify spring upstream to allow for arbitrary setup code to be inserted into the binstub, and optionally create a gem dependency on that future version of spring.
  2. Monkey patch Spring to accomplish # 1 until it can be released.
  3. Modify spring upstream to call a hook defined in spring commands gems like this. In the hook callback, edit the generated binstub to add the appropriate line.
  4. Use the at_exit callback accomplish # 3, while ensuring that the binstub command was just run outside the test environment.

Any other options I'm missing? What do you think is the best way to move forward?

merhard commented

merhard@f05e17f
merhard/spring@3d5653e

Thoughts on this code as a solution?

nilbus commented

That should do the trick

dankohn commented

This fix had been working for me but is now causing an error. I'm not sure what has changed.

$ spring rspec
/Users/dan/Dropbox/Documents/dev/chewy/bin/rspec:7:in `<top (required)>': undefined method `configuration' for RSpec:Module (NoMethodError)
    from /Users/dan/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activesupport-4.1.4/lib/active_support/dependencies.rb:241:in `load'
    from /Users/dan/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activesupport-4.1.4/lib/active_support/dependencies.rb:241:in `block in load'
    from /Users/dan/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activesupport-4.1.4/lib/active_support/dependencies.rb:232:in `load_dependency'
    from /Users/dan/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activesupport-4.1.4/lib/active_support/dependencies.rb:241:in `load'
    from /Users/dan/.rbenv/versions/2.1.2/lib/ruby/2.1.0/rubygems/core_ext/kernel_require.rb:55:in `require'
    from /Users/dan/.rbenv/versions/2.1.2/lib/ruby/2.1.0/rubygems/core_ext/kernel_require.rb:55:in `require'
    from -e:1:in `<main>'

Based on wspurgin/rspec-sidekiq#51, adding require rspec/core fixed it.

#!/usr/bin/env ruby
begin
  load File.expand_path("../spring", __FILE__)
rescue LoadError
end
require 'bundler/setup'
require 'rspec/core'
RSpec.configuration.start_time = Time.now
load Gem.bin_path('rspec-core', 'rspec')
merhard commented

Which versions of spring and rspec are you using?

dankohn commented

gem 'spring', '1.1.3'
gem 'spring-commands-rspec', '1.0.2'
gem 'rspec-rails', '3.0.2'

Dan Kohn mailto:dan@dankohn.com
tel:+1-415-233-1000

On Fri, Aug 1, 2014 at 8:42 AM, merhard notifications@github.com wrote:

Which versions of spring and rspec are you using?

—
Reply to this email directly or view it on GitHub
#18 (comment)
.

merhard commented

@dankohn
Do you have an example application that reproduces this? I don't get the error in my application.

Per https://github.com/rails/spring#use-without-adding-to-bundle, shouldn't you be using bin/rspec rather than spring rspec? I'm not sure if this has anything to do with the issue.

Does:

RSpec.configuration.start_time = Time.now if defined? RSpec.configuration

work instead of:

require 'rspec/core'
RSpec.configuration.start_time = Time.now

?

My benchmark tests in Ruby 1.9.3 show the former to be much faster than the latter.

module RSpec; end
require 'benchmark'

Benchmark.bm do |bm|
  bm.report('defined false:') do
    1000.times do
      RSpec.configuration.start_time = Time.now if defined? RSpec.configuration
    end
  end
  bm.report('require:      ') do
    1000.times do
      require 'rspec/core'
      RSpec.configuration.start_time = Time.now
    end
  end
  bm.report('defined true: ') do
    1000.times do
      RSpec.configuration.start_time = Time.now if defined? RSpec.configuration
    end
  end
end
# >>                 user       system     total       real
# >> defined false:  0.000000   0.000000   0.000000 (  0.000201)
# >> require:        0.390000   0.040000   0.430000 (  0.423843)
# >> defined true:   0.000000   0.000000   0.000000 (  0.000687)
dankohn commented

Yes, your code works just as well. Thanks!

Dan Kohn mailto:dan@dankohn.com
tel:+1-415-233-1000

On Fri, Aug 1, 2014 at 11:18 AM, merhard notifications@github.com wrote:

@dankohn https://github.com/dankohn
Do you have an example application that reproduces this? I don't get the
error in my application.

Per https://github.com/rails/spring#use-without-adding-to-bundle,
shouldn't you be using bin/rspec rather than spring rspec? I'm not sure
if this has anything to do with the issue.

Does:

(RSpec.configuration.start_time = Time.now) if defined? RSpec.configuration

work instead of:

require 'rspec/core'RSpec.configuration.start_time = Time.now

?

My benchmark tests in Ruby 1.9.3 show the former to be much faster than
the latter.

module RSpec; endrequire 'benchmark'
Benchmark.bm do |bm|
bm.report('defined false:') do
1000.times do
(RSpec.configuration.start_time = Time.now) if defined? RSpec.configuration
end
end
bm.report('require: ') do
1000.times do
require 'rspec/core'
RSpec.configuration.start_time = Time.now
end
end
bm.report('defined true: ') do
1000.times do
(RSpec.configuration.start_time = Time.now) if defined? RSpec.configuration
end
endend# >> user system total real# >> defined false: 0.000000 0.000000 0.000000 ( 0.000201)# >> require: 0.390000 0.040000 0.430000 ( 0.423843)# >> defined true: 0.000000 0.000000 0.000000 ( 0.000687)

—
Reply to this email directly or view it on GitHub
#18 (comment)
.

merhard commented

@dankohn Did using bin/rspec work instead of spring rspec?

If it does, I'm not sure I would need to update my pull request since spring specifically says to use that instead.

If it doesn't, it would be nice to have this error be reproducible so the change to the code can be wrapped in a test.

dankohn commented

Yes, I can confirm that ./bin/rspec works with if defined? RSpec.configuration and fails without it. spring rspec works the same. rspec works either way.

I'm unclear how to write a test for this, but I'm happy to test a fork.

merhard commented

I noticed I put guard-rspec in my Gemfile incorrectly per its README.

Replacing gem 'guard-rspec', group: [:development, :test] with:

gem 'guard-rspec', group: :development, require: false

fixed this RSpec load time issue for me. Note that I was having this issue when running my specs with and without guard.

Both gem 'guard-rspec', group: [:development, :test], require: false and gem 'guard-rspec', group: :development also worked.

Is anyone's RSpec load time output still incorrect after making this change and not using the RSpec.configuration.start_time = Time.now line from earlier in this discussion? Anyone have this issue and does not have guard-rspec in their Gemfile?

jonleighton commented

I believe this was fixed by #22