Monday, August 13, 2018

Profiling pytest startup

I'm a fan of pytest (http://www.pytest.org), yet, it seems that the startup time for running tests locally in the app I'm working on is slowly ramping up, so, I decided to do a profile to see if there was anything I could do to improve that.

The first thing I did was creating a simple test and launching it from the PyDev (http://www.pydev.org/) profile view -- it enables any launch done in PyDev to show its performance profile on PyVmMonitor (https://www.pyvmmonitor.com).

Note that this is an integration test that is starting up a big application, so, the total time just to startup all the fixtures which make the application live and shut down the fixtures is 15 seconds (quite a lot IMHO).

The first thing I noticed looking the profile is that 14% of that time seems to be creating a session temp dir:


After investigating a bit more it seems that there is a problem in the way the fixture used make_numbered_dir (it was passing a unicode when it should be a str on Python 2) and make_numbered_dir had an issue where big paths were not removed.

So, pytest always visited my old files every time I launched any test and that accounted for 1-2 seconds (I reported this particular error in: https://github.com/pytest-dev/pytest/issues/3810).

Ok, down from 15 to 13 seconds after manually removing old files with big paths and using the proper API with str on Py2.

Now, doing a new profile with that change has shown another pytest-related slowdown doing rewrites of test cases. 


This is because of a feature of pytest where it'll rewrite test files to provide a prettier stack trace when there's some assertion failure.

So, I passed --assert=plain to pytest and got 3 more seconds (from 13 down to 10) -- it seems all imports are a bit faster with the import rewrite disabled, so, I got an overall improvement there, not only in that specific part of the code (probably not nice on CI where I want to have more info, but seems like a nice plus locally, where I run many tests manually as I think the saved time for those runs will definitely be worth it even with less info when some assertion fails).

Now, with that disabled the next culprit seems to be getting its plugins to load:



But alas, it uses setuptools and I know from previous experience that it's very hard to improve that (it is very greedy in the way it handles loading metadata, so, stay away unless you're ok in wasting a lot of time on your imports) and the remainder of the time seems to be spread out importing many modules -- the app already tries to load things as lazy as possible... I think I'll be able to improve on that to delay some imports, but Python libraries are really hard to fix as everyone imports everything in the top of the module.

Well, I guess going from 15 s to 10 s with just a few changes is already an improvement in my case for an integrated tests which starts up the whole app (although it could certainly be better...) and I think I'll still be able to trim some of that time doing some more imports lazily -- although that's no longer really pytest-related, so, that's it for this post ;)