TransactionTestCases run incredibly slowly since 1.7.4

[Steve Jalim]

Hi

On a project with a reasonable number of tests (~1600) the overall performance of our test suite under Django 1.7.3 averages around 1 second per test (27 mins total - not amazing, but tolerable)

On 1.7.4, the identical codbase takes (literally) several hours to run.

Something was clearly up, which I briefly discussed with @timograham on #django-dev.

Git bisect on the 1.7.x/stable branch reveals the issue to be caused by commit 478546fcef38d95866a92bc44d10e15b26c7254c

(My read of that commit and related ticket is that a short-term patch was put in to fix an edge case with migrating contenttypes, but I'm happy to be corrected. That patch will have to stick around until 1.9, not 1.8 it seems)

Digging a little deeper, I put in some naive print-based logging to see how often is_latest_migration_applied and loader.load_disk() are called.

(For context: our codebase has 50 1.7-era migrations, across 23 apps)

For TestCases, neither of the above is called between tests - they are only called during test DB bootstrap (multiple times, in line with the existence of multiple migrations).

However, for TransactionTestCases, between each and every test is_latest_migration_applied is called around 100 times, each calling loader.load_disk twice.

We have a relatively high proportion of TransactionTestCases (roughly 75%+), but am pretty sure we can't be alone in experiencing this - it looks like something that will affect every codebase with TransactionTestCases.

This is all against Postgres9.3, but very similar behaviour (with different timings) is apparent when running against in-memory sqlite -- ruling out DB bottlenecks as the sole/key cause.

I'm not close enough to the migrations framework to have a decent picture of things, but my key thought is: loader.load_disk() seems to be taking all the resource, because its' called so often. Does it have to be called quite so frequently?

Cheers folks - happy to add more detail as needed, but I cannot share the project (which I know is a PITA)

Steve

[Steve Jalim]

Bit of extra info: our development machines (and CI box) are all Vagrant boxes, so if there is a lot of disk-seeking going on (and I may be wrong about that) it may mean the issue is magnified in that context

[Steve Jalim]

Update: MarkusH kindly put in some time to discuss on #django-dev and ultimately suggested seeing if using the private available_apps API helps make TransactionTestCases fast again.

It does, at least in the limited canary test case I'm using.

However, it doesn't feel like a sustainable solution, if for no other reason than it's a private API. (The overhead of updating ~300 TransactionTestCases is not appealing either, I must admit :o) )

[Markus Holtermann]

This issue is directly related to the way I fixed #24075.

Unfortunately I see no solution for 1.7 and 1.8 that solves both issues. So we either revert #24075 and hope to get #24100 solved for 1.9 (which in turn solved this issue) or we stick to the current limitation. I'm a bit torn. #24075 bit me a couple of times and was annoying in the end.

[Steve Jalim]

@MarkusH - Would this work? -> If #24075 was fixed primarily to aid the development of Django itself (and I'm happy to be corrected on that), would it be viable to park those (stopgap/temporary) changes behind a 'private' (as in private API-style, but still documented) feature flag? Then anyone hacking on Django who hits it can enable it, and everyone else who is building on Django don't get affected?

[Markus Holtermann]

I'm about to revert the patches for #24075.

[Markus Holtermann]

Fixed in bd3d796ecd9a66832ad26024df65caeb63b60a5d and 2832a9b028c267997b2fd3dd0989670d57cdd08f.

[Steve Jalim]

Thanks for this MarkusH - I appreciate that it must have been a frustrating decision to take.

Assuming there's no 1.7.5 (rather than being presumptuous that there will be), will this likely make it into 1.8?

Cheers
Steve

[Tim Graham]

This was reverted on the 1.7 branch as well. 1.7.5 will likely be released concurrently with 1.8 beta in about a week.