We recently upgraded to rspec2 / rails 3 and our specs are taking a
very long time to run. It takes nearly 12 minutes before the first
dot comes out. Before the upgrade, our entire suite of 6000+ specs
would run in about 6 minutes.
The majority of the delay seems to be during the loading of the spec
files. Adding instrumentation to the rspec-core lib/rspec/core/
command_line.rb, you can see that a large portion of the time is spent
in the load_spec_files method
puts "after options.configure #{Time.now}"
@configuration.load_spec_files
puts "after loading spec files stream #{Time.now}"
after options.configure Tue Oct 25 15:34:18 -0700 2011
after loading spec files stream Tue Oct 25 15:46:20 -0700 2011
As you can see, 12 min and 2 seconds were spent in the load_spec_files
method.
I'm trying to use ruby-prof to characterize the problem, but I keep
getting the following error:
/Library/Ruby/Gems/1.8/gems/ruby-prof-0.10.8/lib/ruby-prof.rb:62:in
`measure_mode=': can't set measure_mode while profiling (RuntimeError)
from /Library/Ruby/Gems/1.8/gems/ruby-prof-0.10.8/lib/ruby-prof.rb:
62:in `figure_measure_mode'
from /Library/Ruby/Gems/1.8/gems/ruby-prof-0.10.8/lib/ruby-prof.rb:67
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler/
runtime.rb:68:in `require'
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler/
runtime.rb:68:in `require'
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler/
runtime.rb:66:in `each'
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler/
runtime.rb:66:in `require'
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler/
runtime.rb:55:in `each'
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler/
runtime.rb:55:in `require'
from /Library/Ruby/Gems/1.8/gems/bundler-1.0.18/lib/bundler.rb:120:in
`require'
from /Users/myusername/code/mycompany/www/config/application.rb:7
from /Library/Ruby/Site/1.8/rubygems/custom_require.rb:29:in
`gem_original_require'
from /Library/Ruby/Site/1.8/rubygems/custom_require.rb:29:in
`require'
from /Users/myusername/code/mycompany/www/config/environment.rb:2
from /Library/Ruby/Site/1.8/rubygems/custom_require.rb:29:in
`gem_original_require'
from /Library/Ruby/Site/1.8/rubygems/custom_require.rb:29:in
`require'
from /Users/myusername/code/mycompany/www/spec/spec_helper.rb:9
from /Library/Ruby/Site/1.8/rubygems/custom_require.rb:29:in
`gem_original_require'
from /Library/Ruby/Site/1.8/rubygems/custom_require.rb:29:in
`require'
from /Users/myusername/code/mycompany/www/spec/models/user_spec.rb:7
from ./twospecs.rb:5:in `load'
from ./twospecs.rb:5
from ./twospecs.rb:5:in `map'
from ./twospecs.rb:5
from /Library/Ruby/Gems/1.8/gems/ruby-prof-0.10.8/bin/ruby-prof:
243:in `load'
from /Library/Ruby/Gems/1.8/gems/ruby-prof-0.10.8/bin/ruby-prof:243
from /usr/bin/ruby-prof:19:in `load'
from /usr/bin/ruby-prof:19
My setup is the following:
I have a script RAILS_ROOT/twospecs.rb that contains the following:
$LOAD_PATH.unshift( "/Users/myusername/code/mycompany/www/spec" )
files_to_run = ["spec/models/user_spec.rb", "spec/models/kid_spec.rb"]
files_to_run.map {|f| load File.expand_path(f) }
Then I run it with ruby-prof:
ruby-prof twospecs.rb
The gem versions I'm using are:
bundle show rspec
/Library/Ruby/Gems/1.8/gems/rspec-2.6.0
bundle show ruby-prof
/Library/Ruby/Gems/1.8/gems/ruby-prof-0.10.8
bundle show rails
/Library/Ruby/Gems/1.8/gems/rails-3.0.10
I'm hoping the group can either tell me a) the root of my performance
problems if this is a known problem or b) how to profile the boot time
of an rspec suite (where boot time is the time before the first dot is
printed).
_______________________________________________
rspec-users mailing list
rspec-users@rubyforge.org
http://rubyforge.org/mailman/listinfo/rspec-users
