Load time incorrect with Spring #18

Closed
nilbus opened this Issue Jun 4, 2014 · 17 comments

Comments

Projects
None yet
5 participants
@nilbus

nilbus commented Jun 4, 2014

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

This comment has been minimized.

Show comment
Hide comment
@jonleighton

jonleighton Jun 4, 2014

Owner

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

Owner

jonleighton commented Jun 4, 2014

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

@merhard

This comment has been minimized.

Show comment
Hide comment
@merhard

merhard Jun 12, 2014

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.

merhard commented Jun 12, 2014

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

This comment has been minimized.

Show comment
Hide comment

nilbus commented Jun 12, 2014

👍

@zorab47

This comment has been minimized.

Show comment
Hide comment
@zorab47

zorab47 Jun 18, 2014

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

zorab47 commented Jun 18, 2014

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

@zorab47 zorab47 referenced this issue in guard/guard-rspec Jun 18, 2014

Closed

Load time inaccurate #268

@dankohn

This comment has been minimized.

Show comment
Hide comment
@dankohn

dankohn Jul 14, 2014

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

dankohn commented Jul 14, 2014

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

@nilbus

This comment has been minimized.

Show comment
Hide comment
@nilbus

nilbus Jul 14, 2014

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?

nilbus commented Jul 14, 2014

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 pushed a commit to merhard/spring-commands-rspec that referenced this issue Jul 14, 2014

@merhard

This comment has been minimized.

Show comment
Hide comment
@merhard

merhard Jul 14, 2014

merhard@f05e17f
merhard/spring@3d5653e

Thoughts on this code as a solution?

merhard commented Jul 14, 2014

merhard@f05e17f
merhard/spring@3d5653e

Thoughts on this code as a solution?

@nilbus

This comment has been minimized.

Show comment
Hide comment
@nilbus

nilbus Jul 14, 2014

That should do the trick

nilbus commented Jul 14, 2014

That should do the trick

@dankohn

This comment has been minimized.

Show comment
Hide comment
@dankohn

dankohn Aug 1, 2014

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 philostler/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')

dankohn commented Aug 1, 2014

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 philostler/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

This comment has been minimized.

Show comment
Hide comment
@merhard

merhard Aug 1, 2014

Which versions of spring and rspec are you using?

merhard commented Aug 1, 2014

Which versions of spring and rspec are you using?

@dankohn

This comment has been minimized.

Show comment
Hide comment
@dankohn

dankohn Aug 1, 2014

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)
.

dankohn commented Aug 1, 2014

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

This comment has been minimized.

Show comment
Hide comment
@merhard

merhard Aug 1, 2014

@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)

merhard commented Aug 1, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@dankohn

dankohn Aug 1, 2014

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)
.

dankohn commented Aug 1, 2014

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

This comment has been minimized.

Show comment
Hide comment
@merhard

merhard Aug 1, 2014

@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.

merhard commented Aug 1, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@dankohn

dankohn Aug 1, 2014

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.

dankohn commented Aug 1, 2014

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 pushed a commit to merhard/spring-commands-rspec that referenced this issue Aug 16, 2014

merhard pushed a commit to merhard/spring-commands-rspec that referenced this issue Aug 16, 2014

@merhard

This comment has been minimized.

Show comment
Hide comment
@merhard

merhard Aug 18, 2014

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?

merhard commented Aug 18, 2014

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

This comment has been minimized.

Show comment
Hide comment
@jonleighton

jonleighton Dec 9, 2014

Owner

I believe this was fixed by #22

Owner

jonleighton commented Dec 9, 2014

I believe this was fixed by #22

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment