I looked into the slowest tests on a project that’s pretty young/new for us. Luckily finding the slow(est) tests is trivially easy when Jenkins is your CI server as you can click on “Test Result” and see a breakdown of execution times by test.
I was very surprised to see that the slowest test was one for code that’s for formatting log messages. Peculiarly there was one test took about 0.9 seconds, and the other 3 in the same test class (for the same module) took a combined 26 milliseconds. Clearly that test was the candidate to look at.
Looking at it however, it wasn’t obvious why it was slow. The only difference in this specific test was it was testing the case when the log record contained stacktrace info and that that stacktrace info was included on the emitted log message. Aside from that, it was virtually identical to the other 3 tests in the test class.
I then spent some time trying to debug why it was slow. As it turns out, pytest (which we use for running the tests) has a
--durations=N argument that when supplied will give you a breakdown of the N slowest parts of your test suite. This is even more finely grained than you think as it breaks it down not only by the test time itself, but also setup & teardown times. What was surprising was what I saw when running just the 4 tests in that class – it revealed that the slow part was the setup() for that one test.
I then instrumented the setup method (added timing statements) to try and figure out what the slowest part of the setup was. As it turned out, it was the line that just instantiated the class under test. The weird part: this line was identical for all the tests in this test class so why was it slow for this particular test?
I then wondered if it was an ordering thing: pytest runs all tests in a specific order. Ie if you run them once, then run them again, it’s guaranteed that they’ll be run in the same order. I found a plugin (https://pypi.org/project/pytest-random-order/) that randomizes the order of the tests, and this was very insightful as suddenly one of the other tests in the class was the slowest. As it turned out, it was the time to instantiate the class under test for the first time that was slow. So the first test in the test class will always pay this “tax”. I believe the reason is I/O related (the class under test inherits from Python’s logging.FileHandler class, so I’m guessing that there’s some I/O operation that’s done lazily on demand).
I’ve now committed the change to have the tests run randomly (which is a good practice anyways as otherwise you can accidentally write tests that depend on execution order). Aside from that, some good practice with debugging skills, and finding that --durations argument for pytest is almost definitely going to be useful in the future. And I do like having test execution randomized, as I’ve been bitten by non-random test execution in the past.