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:infigure_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:inrequire’
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:inrequire’
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:inrequire’
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:ingem_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:ingem_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:ingem_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:inload’
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:inload’
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).