[rspec-users] problem profiling rspec boot time with ruby-prof

jefflab jlabarge at gmail.com
Wed Oct 26 14:02:24 EDT 2011


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).


More information about the rspec-users mailing list