Rodrigo Rosenfeld Rosas
2011-Apr-16 14:05 UTC
[rspec-users] rspec execution speed footprint
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.
On Apr 16, 2011, at 9:05 AM, Rodrigo Rosenfeld Rosas wrote:> 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 timeNot 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.> ... 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...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
Rodrigo Rosenfeld Rosas
2011-Apr-17 00:43 UTC
[rspec-users] rspec execution speed footprint
Em 16-04-2011 12:57, David Chelimsky escreveu:> On Apr 16, 2011, at 9:05 AM, Rodrigo Rosenfeld Rosas wrote: > >> 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 > 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...> 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.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...> 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.I would be glad if there were a couple of hundred example! :D Actually, there are only 54 examples (what a coincidence, right? ;) ). 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)>> 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... > 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.