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.

This forum is not affiliated to the Ruby language, Ruby on Rails framework, nor any Ruby applications discussed here.

| Privacy Policy | Terms of Service | Remote Ruby Jobs