Our full-system integration tests take too long to run: between five and eight minutes in a highly optimised CI environment, and over an hour if run on a developer’s laptop.
One of the ways we’re trying to manage this is by logging which tests take the longest and then printing them out at the end of the run, eg:
In this particular run refundsinvoicesspec.rb is taking three minutes to complete. If we divide that by the eight workers on that CI instance, that’s adding a good 22 seconds to each run, assuming a perfect distribution of tests between workers.
We can dive further using rspec --profile:
> bundle exec rspec --profile -- spec/features/admin/refunds_invoices_spec.rb
63.36 seconds ./spec/features/admin/refunds_invoices_spec.rb:45
14.9 seconds ./spec/features/admin/refunds_invoices_spec.rb:642
9.39 seconds ./spec/features/admin/refunds_invoices_spec.rb:372
...
Unfortunately, the test case at line 45 is 329 lines long. There’s definitely ways we can optimise that, but without measuring exactly where in those lines it’s spending its time we have no way of knowing where the biggest impact will be.
We could measure where the problem areas are by adding lots of puts Time.now — start lines in at random points, but this isn’t our only problem test, and that method gets tiresome very quickly.
Instead, I’ve written a small rspec helper which wraps every Capybara DSL method and prints out how long each operation took. For example:
> CAPYBARA_TIMERS=1 bundle exec rspec spec/features/admin/refunds_invoices_spec.rb:45
Run options: include {:locations=>{"./spec/features/admin/refunds_invoices_spec.rb"=>[45]}}
3.64s spec/support/features/session_helpers.rb:8 visit "/administration"
0.73s spec/features/admin/refunds_invoices_spec.rb:46 visit "/administration/refund_invoices"
0.02s spec/features/admin/refunds_invoices_spec.rb:48 assert_text "Refunds"
0.06s spec/features/admin/refunds_invoices_spec.rb:48 within_element "h1.MPanelGroup-heading"
0.11s spec/features/admin/refunds_invoices_spec.rb:50 fill_in "Invoice ID"
...
The first column in the output is the time the operation took. The second is the filename and line number the Capybara method was called from. Third is the Capybara method itself, and the final column is the first argument.
At the end of the run we’re also given a total along with RSpec’s usual timing information, allowing us to see what percentage of the test’s time was spent in Capybara:
CAPYBARA TOTAL 45.24s
Finished in 52.38 seconds (files took 3.14 seconds to load)
Analysing the log we see a repeated pattern:
...
0.04s spec/support/integration_helpers.rb:61 find "thead th"
0.24s spec/support/integration_helpers.rb:36 path Array
0.16s spec/support/integration_helpers.rb:63 path Array
0.03s spec/support/integration_helpers.rb:63 find Array
0.02s spec/features/admin/refunds_invoices_spec.rb:346 assert_text "2018-03-19"
0.05s spec/support/integration_helpers.rb:61 find "thead th"
0.16s spec/support/integration_helpers.rb:36 path Array
0.15s spec/support/integration_helpers.rb:63 path Array
0.02s spec/support/integration_helpers.rb:63 find Array
0.02s spec/features/admin/refunds_invoices_spec.rb:347 assert_text "awaiting"
...
In this run we see this pattern at least 10 times. Looking at integration_helpers line 61 we find the following method, used for finding a particular cell in a table based on its column heading and row:
def cell_for_column(text, row: 1)
th = find('thead th', text: text, match: :prefer_exact)
column = element_index(th)
find(:xpath, "#{th.path}/ancestor::table").find(:css, "tbody tr:nth-of-type(#{row}) > :nth-child(#{column})")
end
This method calls .path twice and .find twice. Fortunately, if the element already exists on the page, .find is quite fast, but .path is taking between 100 and 300 ms per call.
I optimised the method to only use find calls and never call .path:
def cell_for_column(text, row: 1)
th = find('thead th', text: text, match: :prefer_exact)
column = th.find(:xpath, '..').all('th').index(th) + 1
table = th.find(:xpath, 'ancestor::table')
table.find(:css, "tbody tr:nth-of-type(#{row}) > :nth-child(#{column})")
end
Re-running the spec with this version shaves off a good 15 seconds!
...
0.04s spec/support/integration_helpers.rb:61 find "thead th"
0.01s spec/features/admin/refunds_invoices_spec.rb:346 assert_text "2018-03-19"
0.05s spec/support/integration_helpers.rb:61 find "thead th"
0.01s spec/features/admin/refunds_invoices_spec.rb:347 assert_text "awaiting"
...
CAPYBARA TOTAL 26.72s
Finished in 36.31 seconds (files took 3.21 seconds to load)
The code to track time spent in Capybara is in this gist. Simply drop it in your spec/support folder in your Rails project and preface your spec run with CAPYBARA_TIMERS=1