There are a lot of reasons why test suites for large applications become slow. One of them - errant sleep statements in your code - is easy to fix and, with the rspec-sleep_study gem, easy to find.
Any time you find a spec that takes a nice, round number of seconds to complete, you should immediately be suspicious. Especially when the code under test integrates with another service or makes any kind of network calls.
Top 4 slowest examples (40.14 seconds, 96.0% of total time):
IntercomClient::post when an error is raised when it's a retryable error retries
20.04 seconds ./spec/services/data/intercom_client_spec.rb:45
IntercomClient::get when an error is raised when it's a retryable error retries
20.01 seconds ./spec/services/data/intercom_client_spec.rb:23
IntercomClient::get when an error is raised raises the error
0.07472 seconds ./spec/services/data/intercom_client_spec.rb:17
IntercomClient::post when an error is raised raises the error
0.01893 seconds ./spec/services/data/intercom_client_spec.rb:39
Finished in 41.82 seconds (files took 8.88 seconds to load)
4 examples, 0 failures
This is usually a sign that you have a sleep somewhere in your code, and your specs are blocking while they wait for the sleeps to complete.
The solution to this is generally easy: you need to stub out the sleep statements or the sleep interval in your specs. But how do you find out which specs are blocking, and where, so that you can fix them? That's where Sleep Study comes in.
Sleep Study uses Ruby's TracePoint class to wrap every C function call and return executed by your code. If it detects a sleep function, it records the time spent sleeping and then prints a report showing you both the spec and the line(s) of code responsible.
$ gem install rspec-sleep_study
$ rspec --format RSpec::SleepStudy spec/services/data/intercom_client_spec.rb
...
The following examples spent the most time in `sleep`:
20.013 seconds: ./spec/services/data/intercom_client_spec.rb:23
- 20.013 seconds: /opt/apps/vendor/ruby/2.5.0/gems/retryable-2.0.4/lib/retryable/configuration.rb:36
20.001 seconds: ./spec/services/data/intercom_client_spec.rb:45
- 20.001 seconds: /opt/apps/vendor/ruby/2.5.0/gems/retryable-2.0.4/lib/retryable/configuration.rb:36
Now we know that our specs are indeed blocking on sleep, and we have an idea of where to look in our code: somewhere in our client class we're calling Retryable.
def self.get(endpoint)
Retryable.retryable(:tries => 5, :sleep => RETRY_SLEEP) do
JSON.parse RestClient.get(endpoint, HEADERS)
end
end
def self.post(endpoint, data)
Retryable.retryable(:tries => 5, :sleep => RETRY_SLEEP) do
JSON.parse RestClient.post(endpoint, data.to_json, HEADERS)
end
end
And now that we've found that, we can make our specs run way faster by stubbing that RETRY_SLEEP constant:
before do
stub_const("IntercomClient::RETRY_SLEEP", 0)
end
Top 4 slowest examples (0.08328 seconds, 4.3% of total time):
IntercomClient::post when an error is raised raises the error
0.0358 seconds ./spec/services/data/intercom_client_spec.rb:39
IntercomClient::get when an error is raised when it's a retryable error retries
0.02302 seconds ./spec/services/data/intercom_client_spec.rb:23
IntercomClient::get when an error is raised raises the error
0.0135 seconds ./spec/services/data/intercom_client_spec.rb:17
IntercomClient::post when an error is raised when it's a retryable error retries
0.01096 seconds ./spec/services/data/intercom_client_spec.rb:45
Finished in 1.94 seconds (files took 7.54 seconds to load)
4 examples, 0 failures
40 seconds shaved off our build time with a one-line change!
It's important to note that putting trace points around every single C function isn't free, and Sleep Study WILL make your specs run more slowly. Only use it once in a while to find new sleeps that have snuck into your code. Stub those sleeps out, open a PR showing how much faster you made your tests, and then do a victory lap around the office and collect your high fives.
Top comments (0)