Rspec execution speed footprint

Testing RSpec
1

Hi, I would like to figure out if it is possible for me to run my specs
faster than it currently is.

Before start optimizing my specs for speed, I tried to figure out what
was the speed footprint of Rspec boot process itself for starting
executing my specs. So I took my simplest spec with a single fast
example:

time bundle exec rspec ./spec/models/decision_spec.rb
.

Finished in 0.00794 seconds
1 example, 0 failures

real 0m19.202s
user 0m17.649s
sys 0m1.300s

All my specs run in about 54s. That means Rspec itself is responsible
for about a third of the total time… Well, not exactly:

time rails runner “puts 1”
1

real 0m13.918s
user 0m12.805s
sys 0m0.940s

This means I could not get more than 5s in the best case from trying to
optimize Rspec itself… Simple does not worth…

Rails (3.0.7rc2) itself takes about 4s to boot up an empty application:

rails new empty
cd empty
time rails runner “puts 1”
1

real 0m4.000s
user 0m3.440s
sys 0m0.492s

That means I can try to optimize my application boot time first, which
can reduce my specs running time up to 10 seconds…

Then, I tried to give autotest a try in the hope it would skip the boot
process for the next spec executions. But it didn’t. It is not that
smart. It just monitor file changes and call rspec on the possible
affected specs…

So, I would like to know if some of you know a good Ruby profiler that
could show me how much time each method takes on a tree view… For
instance, I enjoy very much the Javascript profiler that comes with
Google Chrome Developer Tool.

I tried adding “-r profile” to .rspec, but the output is not that useful
in my opinion… And the “–profile” Rspec option will only show me the
to 10 slowest examples, but not what is the bottleneck, so I need to do
that manually… Also, it won’t help me getting my Rails application to
boot faster…

Does anyone here knows of a good tool for profiling or finding
bottlenecks on a Rails or Ruby application?

Sorry if I took too long on my question…

Cheers, Rodrigo.

2

On Apr 16, 2011, at 9:05 AM, Rodrigo Rosenfeld R. wrote:

real 0m19.202s
user 0m17.649s
sys 0m1.300s

All my specs run in about 54s. That means Rspec itself is responsible for about
a third of the total time

Not really. If you want a sense of what RSpec is taking, do something
like this:

$ echo ‘1000.times do |n|
describe n do
it “is #{n}” do
n.should eq(n)
end
end
end’ > example.rb
$ time rspec example.rb
…
…

Finished in 0.51265 seconds
1000 examples, 0 failures

real 0m1.063s
user 0m0.877s
sys 0m0.131s

So here, it took just over 1/2 a second to run 1000 examples and output
a dot for each.

This is admittedly slower than MiniTest/Spec

$ echo 'require “minitest/autorun”

require “minitest/spec”

1000.times do |n|
describe “Spec#{n}” do
it “is #{n}” do
assert_equal(n,n)
end
end
end
’ > example.rb
[david: rspec-core (master)]$ time ruby example.rb
Loaded suite example
Started
…
…
Finished in 0.242546 seconds.

1000 tests, 1000 assertions, 0 failures, 0 errors, 0 skips

Test run options: --seed 24068

real 0m0.571s
user 0m0.537s
sys 0m0.029s

But if you have a couple of hundred examples that are taking 54 seconds,
it is not because of RSpec.

That means I can try to optimize my application boot time first, which can
reduce my specs running time up to 10 seconds…

Then, I tried to give autotest a try in the hope it would skip the boot process
for the next spec executions. But it didn’t. It is not that smart. It just monitor
file changes and call rspec on the possible affected specs…

Check out spork. It loads the env once, and runs the suite in a fork
each time you run it.

So, I would like to know if some of you know a good Ruby profiler that could
show me how much time each method takes on a tree view… For instance, I enjoy
very much the Javascript profiler that comes with Google Chrome Developer Tool.

I tried adding “-r profile” to .rspec, but the output is not that useful in my
opinion… And the “–profile” Rspec option will only show me the to 10 slowest
examples, but not what is the bottleneck, so I need to do that manually… Also,
it won’t help me getting my Rails application to boot faster…

Does anyone here knows of a good tool for profiling or finding bottlenecks on a
Rails or Ruby application?

Sorry if I took too long on my question…

Cheers, Rodrigo.

There is ruby-prof, and Rubnius has some profiling tools that look very
interesting.

HTH,
David

3

Em 16-04-2011 12:57, David C. escreveu:

1 example, 0 failures

real 0m19.202s
user 0m17.649s
sys 0m1.300s

All my specs run in about 54s. That means Rspec itself is responsible for about
a third of the total time
Not really.

Yes, I know. That is why I continued in the e-mail:

… Well, not exactly:

time rails runner “puts 1”
1

real 0m13.918s
user 0m12.805s
sys 0m0.940s

This means I could not get more than 5s in the best case from trying to optimize
Rspec itself… Simple does not worth…

I didn’t say it was responsible for the 5s, but that was just some
theorical limit considering the rest of the analysis…

…
…

…

Finished in 0.51265 seconds
1000 examples, 0 failures

real 0m1.063s
user 0m0.877s
sys 0m0.131s

So here, it took just over 1/2 a second to run 1000 examples and output a dot
for each.

Yes, but this is a pure Ruby and Rspec example. It doesn’t mean
rspec-rails will have the same speed footprint…

But anyway, I know that I should not be concerned about Rspec footprint
in my case for now. For sure, I should start optimizing my application
boot footprint and then my specs itself…

end
end
'> example.rb
[david: rspec-core (master)]$ time ruby example.rb
Loaded suite example
Started

…
…

But if you have a couple of hundred examples that are taking 54 seconds, it is
not because of RSpec.

I would be glad if there were a couple of hundred example! :smiley: Actually,
there are only 54 examples (what a coincidence, right? :wink: ). The most
time consuming example is an integration spec that takes about 2
seconds. All specs take about 20 seconds according to Rspec. The
remaining 34 seconds are related to Rails boot, Bundler loading, Rake
loading and Rspec. I forgot to show this other result (I thought I did,
but I just realized that I only sent the time for a new Rails
application). This one is used by the real application:

time rails runner ‘puts 1’
1

real 0m14.855s
user 0m12.973s
sys 0m0.968s

For bundler:

time bundle exec ruby -e ‘puts 1’
1

real 0m2.268s
user 0m1.868s
sys 0m0.328s

for rake:

time rake -T
real 0m8.418s
user 0m6.768s
sys 0m0.740s

That means, I can speed up the boot process up to 10s. Also it means
that Rspec really doesn’t add much (if something), since 54 (total time)

  • 20 (specs time) =~ 15 (Rails boot) + 2 (Bundler time) + 8 (rake time)

That means I can try to optimize my application boot time first, which can
reduce my specs running time up to 10 seconds…

Then, I tried to give autotest a try in the hope it would skip the boot process
for the next spec executions. But it didn’t. It is not that smart. It just monitor
file changes and call rspec on the possible affected specs…
Check out spork. It loads the env once, and runs the suite in a fork each time
you run it.

Yes, that helped a lot! But not that much if I use “rake spec”. It takes
about 40s (instead of 54s), while the alternative “bundle exec rspec
./path/to/specs.rb” takes 25s (why not 22s?).

Thank you for the hint!

So, I would like to know if some of you know a good Ruby profiler that could
show me how much time each method takes on a tree view… For instance, I enjoy
very much the Javascript profiler that comes with Google Chrome Developer Tool.

I tried adding “-r profile” to .rspec, but the output is not that useful in my
opinion… And the “–profile” Rspec option will only show me the to 10 slowest
examples, but not what is the bottleneck, so I need to do that manually… Also,
it won’t help me getting my Rails application to boot faster…

Does anyone here knows of a good tool for profiling or finding bottlenecks on a
Rails or Ruby application?

Sorry if I took too long on my question…

Cheers, Rodrigo.
There is ruby-prof, and Rubnius has some profiling tools that look very
interesting.

It seems the Graphic profile may help. I’ll take a closer look at it.
I’ve seen a presentation about Rubinius profiling tools in last RubyConf
Brazil if I remember correctly. I’ll take another look at it if
ruby-prof graphic profile doesn’t help me…

Thanks!

Best regards, Rodrigo.