Specjour slow when before(:all) is heavily used
josephlord opened this issue · 7 comments
[Issue renamed for clarity and information of new readers - Was "Specjour slower than basic rspec on 4 core machine"]
It might well be something about my project set up but when I run specjour it is taking longer than normal rspec and it can take more than three times as long as for parallel_rspec on the same machine. This is pretty consistent although obviously there is some variation
Can you suggest what might be causing this and if there is anything I can do about it? Or any diagnosis I could provide.
$ time bundle exec rspec spec
Finished in 3 minutes 34.18 seconds
778 examples, 0 failures, 28 pending
real 3m48.092s
user 3m14.260s
sys 0m5.332s
$ time bundle exec specjour spec
Looking for listeners...
No listeners found on this machine, starting one...
Workers found: 4
jtl.me.uk (4)
Loading RSpec environment... completed in 14.104135037s
Finished in 4 minutes 49.54 seconds
778 examples, 0 failures, 28 pending
real 5m27.559s
user 13m58.396s
sys 0m22.745s
$ time bundle exec parallel_rspec spec
4 processes for 57 specs, ~ 14 specs per process
Finished in 24.74 seconds
211 examples, 0 failures, 12 pending
Finished in 27.67 seconds
220 examples, 0 failures, 2 pending
Finished in 52.31 seconds
161 examples, 0 failures, 1 pending
Finished in 1 minute 14.52 seconds
186 examples, 0 failures, 13 pending
778 examples, 0 failures, 28 pendings
Took 90.845140227 seconds
real 1m34.601s
user 3m38.938s
sys 0m6.104s
Wow, that's bizzarre!
Try running head .specjour/performance to see which specs take the longest. Also, try comparing some subdirectories of the test suite. Try timing rspec spec/models, then time specjour spec/models. You can also try running specjour with only one process. In theory, specjour with one process should take only a few seconds longer to run than normal rspec; compare time rspec spec/models with time specjour -w1 spec/models.
I wonder if the rsync is taking a long time… If you run a listener in one terminal window, you should see how long rsync is taking. Run specjour listen in one terminal, then specjour in the other. The listener should spit out some interesting numbers. Oh, perhaps it's a before(:all).
Do you have a before(:all) in spec_helper? Specjour runs before(:all) way more than it should – I need to fix that!
Now that you mention it, things are a little slow. I'm going to dig in.
Just added a simple timing test to the specjour rails app.
sandro/specjour_rails_app@502abca
The test takes 5 seconds to complete in both specjour and rspec. This means the specjour example runner is not the bottleneck. Perhaps it's database_cleaner? Something like that?
I don't have before(:all) in spec_helper but I do (ab)use it heavily to set up the DB before tests. That could well be the issue. If they are running before every test that could completely explain the issue I'm seeing.
I just swapped before(:all) for before(:each) in my worst performing spec and ran it in rspec which showed the massive sort of slowdown I was seeing. It definitely isn't an optimal spec but I think it is pretty clear that it is the before(:all) handling that is the cause of the differences I have been seeing.
parallel_rspec divides the job up sub-optimally by just dividing the spec files into n groups (for n processors) and then letting them run but this naive approach works better where before(:all) is used. Specjour dispatches singly (I think) but loses the efficiency of the before(:all) commonality.
$ time rspec spec/features/project/project_spec.rb
.........................*......*
Finished in 17.65 seconds
33 examples, 0 failures, 2 pending
rspec spec/features/project/project_spec.rb 19.30s user 1.16s system 82% cpu 24.685 total
$ time rspec spec/features/project/project_spec.rb
............*.............*......*
Finished in 2 minutes 22.59 seconds
34 examples, 0 failures, 3 pending
rspec spec/features/project/project_spec.rb 127.49s user 2.64s system 87% cpu 2:29.34 total
By the way should specjour path work? It seemed to be running all specs when called this way rather than specjour dispatch path?
I'm running the same issue... Specjour is taking more time than rspec with 6 workers.
Edit : my coworkers tried to remove the before all statement, without improving the specs... So I think, we have a different "performance" issue.
Yes, specjour runs the before(:all) block before every test. I'll look into fixing this today.