rspec users - Oct 2011 - 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 #{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).

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.