More scouting reports (pt 3)
Following on from part one and part two.
The last post I was looking at fixtures. I haven't fixed up all the fixtures, but as I'm going along I'm fixing them. As it turns out, most of the tests need very few fixtures, but were just pulling in large ones because it's easy. Haven't seen any huge wins on the overall test time yet, but it won't hurt.
Scouting
Fixing tests requires information. There are quite a few timing plugins out there, but I didn't find one that did what I wanted, so I wrote one. Nose timing is based on nose congestion and is a basic plugin to output the time of each test setup and each test. It then outputs them in JSON with a file and line number.
Once I've got those big JSON dumps, I run a secondary hack, it sorts the data and then tries to run git blame on each test. The result is the slowest tests in zamboni and the person who wrote them. And the output is available here. From that, I filed some bugs on those tests and so hopefully other people will fix them.
More timing
Sending stats to django-statsd is giving us quite a lot of information on the tests. Wanting more, I added in a simple timer decorator to the marketplace. In this example I've thrown a timer decorator on to the transformer. Now every time I run the tests with statsd, you'll see how long that method takes:
[master] zamboni $ t mkt/api/tests/test_handlers.py --with-statsd [snip]... ====================================================================== Statsd Keys | Number | Avg (ms) | Total (ms) ---------------------------------------------------------------------- [snip...] cache.memcached.set_many | 1929 | 0.143079 | 276.000 db.mysql.default.execute | 7499 | 0.199227 | 1494.000 django.management.command.loaddata | 9 | 46.555556 | 419.000 [snip...] timer.addons.models.transformer | 120 | 23.441667 | 2813.000
That added key, timer.addons.models.transformer is pretty useful for quick checking how slow a method is. I'm also looking at one that provides a quick profile decorator that hooks in via sys.settrace which I haven't got as useful yet. But it did yield that apps.amo.utils.patched_load method is being called 19,557 times on one test (although I think this fine based on the internals of PIL).
Miscellany
Django has a really slow method for checking if a view returns an a redirect. But it then also goes and calls the resulting URL. Meaning that one request to check you get a redirect results in two requests. That has never been a problem for us and has not resulted in finding any broken code. The redirect targets are tested seperately. What it has done is slowed down our tests by doubling the number of requests. So the most excellent Rob Hudson wrote a simple little replacement assert3xx that doesn't do the extra request.
There's also a matching assertLogin which just checks that the user is redirected to a login.
Next? Finding some of the stupid things zamboni is doing all the time and stopping that.