Day 12 - Investigate your slowest test(s)

[dorothy]

Today’s task is to investigate your slowest tests.

If you happen to use Ruby and RSpec, finding your 10 slowest tests is simply a matter of adding --profile to your test command. If you’re using something else, hopefully a similar flag is only a quick google away.

Once you’ve identified your 10 slowest tests or so, give them each a once-over.

Some things to consider:

1. Are any of these tests duplicates? It’s easier than you might think to accidentally write the same test more than once. You can’t see that you’ve done this by reviewing a diff in a PR, so this type of duplication can often creep into your codebase over time.
2. Can any of these tests be replaced with a faster variant? If you’re testing a conditional in the view, can you use a view spec instead of an integration spec? Can you stub expensive calls? Can you perform less setup? Can you hit less of the stack and still feel confident things work? This video I recorded on integration vs. unit tests might be helpful.
3. Are all these tests still pulling their weight? Remember: slow tests act as a constant drag against your forward progress. Make sure the cost is outweighed by the benefits of keeping them around. I encourage you to be pragmatic. If a very slow test is verifying something that’s not mission-critical, it’s worth considering deleting it.

[jeromedalbert]

Holy cow , rspec --profile surfaced a spec that took 16 seconds to run.

The spec was doing something like this:

it 'returns the top 102 ...' do
  102.times do |i|
    create(:some_record, ...)
  end
  ...

Woot! Even if the business code under test was in practice instructed to process 100 records by its callers, it had no reason to treat 102 or 100 any different by itself, and it worked just as well for any number of records.

So I changed the spec to generate only 3 records:

it 'returns the top ...' do
  3.times do |i|
    create(:record, ...)
  end
  ...

And the spec went from 16 seconds to 0.6 seconds. Huge quick win.

Great tip, thank you!

[1337]

Found out we had a slow test that was waiting in 1 second to verify that something didn’t happen. The code it tested was no longer in use as we removed the feature months ago.
The total duration of that test suite was 5 seconds which is now down to 4 seconds

[julianrubisch]

Good morning!

Today’s episode brutally reminded me of a refactoring I wanted to make that will convert a whole group of fairly slow test into one fairly slow test

I bumped that up in the backlog right away

[hauthorn]

Slowest tests ran at about 800ms a piece.

While this is quite slow, it is testing some rather complex database queries that are easy to mess up when refactoring.

Tried out this cool visualization tool, so that’s something new!

[Christoph]

We recently did improve our database integration tests. Before we applied all migrations before each test which was fine at the beginning, but as more migrations have been added it took more and more time. It’s still valuable for us to know that the migrations all apply, but it’s not so important that we have to verify it for every test.
So now we’re applying all migrations at the start of the whole test suite, and downgrade all of them at the end (we use a tool that supports roll backs). Not only did it trim down the overall execution time of the tests, we also know that each migration continues to work with each other.

[rtem]

rspec --profile was a huge win. We generate PDF reports for our customers, and takes some time to do this… Identified some tests where PDF generation could be stubbed, that dropped test suite time by 15 seconds.
Before:

# rspec --profile -fp 
Finished in 4 minutes 5.3 seconds (files took 7.94 seconds to load)
5474 examples, 0 failures, 72 pending

After:

# rspec --profile -fp 
Finished in 3 minutes 51.8 seconds (files took 8.12 seconds to load)
5474 examples, 0 failures, 72 pending

Unexpected discovery for this excercise was NyanCat formatter. Somebody configured it to be the default one when running tests, and our team likes it a lot… But this what happened when I’ve dropped --format progress (or -fp for short) and nyan started its way:

# rspec
^C
Finished in 4 minutes 29.3 seconds (files took 8.33 seconds to load)
1463 examples, 1 failure, 3 pending

So it took more time to complete ~25% of the test suite (the failure here was test running when I hit ^C)
I guess we’ll have Nyan Cat to let go

[andrewG]

Our slowest test is of course an integration test, which is a form with 45 input fields and it checks if they are saved in db and shown in the UI. It reflects the real app and kind of makes sense, but it’s also possible to reduce the number of those fields, because these fields are dynamically configured in the database. So by reducing the setup we could achieve a win in test performance, but it will take time to refactor.

[mlt]

Our slowest test took 10s… because there was a sleep(10) in there.

Replaced the call to sleep with explicit “time stepping” and the run time went down to 0.5 s instead.

[nckrtl]

My tests are really simple and have low test coverage. Instead of improving my tests which was not really possible in my case, I spent the time creating extra tests instead.

[Hlavicka]

Thanks for these tips.

[vlcinsky]

With my (python) pytest was detection of the slowest tests very simple:

$ pytest --durations 10
==============================  slowest 10 durations
0.42s call     tests/test_auth.py::test_it
0.42s setup    tests/test_custom_settings.py::test_list_users
0.27s call     tests/test_s3_accesspoint.py::test_it
0.16s setup    tests/api/test_user-resources.py::test_delete_invalid_user_resource
0.16s setup    tests/api/test_resource_set-resources.py::test_delete_resource_set_resource
0.15s setup    tests/api/test_feeds.py::test_key_without_access
0.14s setup    tests/api/test_user-resource_sets.py::test_list_users_resource_sets_empty
0.14s setup    tests/api/test_resource_sets.py::test_read_invalid_set
0.14s setup    tests/api/test_resource_sets.py::test_read_set
0.14s setup    tests/api/test_resource_sets.py::test_duplicate_set
============================== short test summary info 

The slowest cases were very simple (single sql query withou filters) so there was nothing to optimize.

There were no duplicates. But as I used another project, I found here two cases to apply http request mocking skill.

[aaron]

I inherited a Rails app with a test suite that takes upwards of 30 minutes to run, mainly because it hits a staging server directly instead of mocks. The long-term plan is to begin applying mocks, but shorter-term, I’ve noticed cases of integration tests being treated like unit tests. Combining them into bigger tests that cover more ground, but don’t repeat setup and teardown, has shaved a few minutes off the overall run. Baby steps!

[martin]

I’ve been writing Elixir for several years, but I never found out about the mix test --slowest option before. It’s great!

[hectorsq]

Curiously my slowest tests are the ones that test the rendering of error pages. I have to do further investigation.

[frankcorso]

Since I use PHP and Laravel, had to find a way to find slow tests. Discovered a flag for PHP Unit of --log-junit phpunit-results.xml which outputs an XML file that includes time to run each test.

This can be passed to the artisan command so:
php artisan test --log-junit phpunit-results.xml

This creates the XML file. If you have a small number of tests, you can CTRL+F for “time=” to find the time for each test and find the slowest ones. Since I have a lot of tests, I had to run this through a parser to pull out the times.

Unfortunately, took the whole 20 minutes to find the flag and the parser needed but I at least now have a list of the slowest tests and made a task to examine those later in the week.

[Linton]

Most of my functional tests fail at the moment, hackery to get things working has had consequences.
No other changes were made.

[Lars]

as expected, the slowest tests were the ones using testcontainers. Spinning up a real database in a docker container has it’s price. Same with @SpringBootTest which starts the whole application and wires up all beans.
Looking forward to JUnit 5.8 which will have the possibility to order tests, then we can tag the slower tests and run them last, which means we get feedback from the fast unit tests first.

[GregA]

I found 5 of the top 10 slowest tests that were testing pagination.

In order to test pagination, you only need 1 record more than the max
records per page. In this situation we were creating almost twice as many records in the database. I didn’t have too much time so I just created n + 1 records instead of almost 2n records. This increased the speed of these 5 tests by about 50%.

These tests can be improved further by setting the desired pagination for each request and/or stubbing the default_per_page for Kaminari.

In general, saving to the database is slow so in the future we might find other ways to speed this up but still give enough confidence.

[nanorepublica]

I spent most of the time adding the ability to record timings to my test cases, which turned out to be fine since my slowest test case was coming in at 0.006365s which I am pretty happy with for now