Problem profiling rspec boot time with ruby-prof

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 #{}"
    puts "after loading spec files stream #{}"

    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

I’m trying to use ruby-prof to characterize the problem, but I keep
getting the following error:

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”] {|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

bundle show ruby-prof

bundle show rails

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

I ended up solving the ruby-prof conflict. The problem was that I had
included the ruby-prof gem in my Gemfile. After removing it and doing
a bundle install everything worked.

I will start a new thread if the profiling results lead to performance
opportunities in rspec boot time.