pytest 5.3.3 much slower than 5.3.2

[frederic-peters]

Hi,

An internal CI job started getting aborted due to timeouts, the only change in installed modules version was pytest. I reproduced the issue locally (a 10× slowdown) and bisected it to

commit 99180939febb6ca4b3ff788cf336b065046653f2
Author: Chris NeJame <chris.t.nejame@gmail.com>
Date:   Wed Jan 15 11:00:42 2020 -0500

    fixtures register finalizers with all fixtures before them in the stack

I also switched back to master to revert that single commit and that was also ok.

Looking at the change, code was previously running with self.argnames == ['request'], after the change it is now computing its list of fixtures as {'_django_clear_site_cache', 'django_db_blocker', 'django_test_environment', '_fail_for_invalid_template_variable', '_dj_autoclear_mailbox', 'request', '_django_setup_unittest'} and this obviously make the tests slower.

plugins: django-3.8.0, localserver-0.5.0, freezegun-0.3.0.post1, django-webtest-1.9.7

[blueyed]

Related to #6492 (pytest-django).
(don't try xdist on top.. ;))

[nicoddemus]

Thanks @frederic-peters!

I'm closing this as duplicate of #6492 then, seems they are the same problem.

[nicoddemus]

@frederic-peters please subscribe to #6492 to track the progress of this problem; we're still trying to figure out if the problem is in pytest or pytest-django.

[SalmonMode]

@frederic-peters that change shouldn't impact self.argnames, but it should impact how often/when things are torn down and rebuilt.

I'm assuming the list you found was the one produced by self._dependee_fixture_argnames(request). If that's the case, then this looks like a normal list, as I looked them up and all of them are either explicitly or indirectly autouse (_django_setup_unittest is autouse and requests django_db_blocker making it autouse in the context of a class). So every time any of them are torn down, they will make sure your fixture is torn down before they go through with their teardowns.

I'm guessing you're doing some parameterization because the only fixture you're requesting is the request fixture. If this is the case, visualize the tree of fixture dependencies, i.e. which fixtures request what. Pytest effectively linearizes this structure into the order they would execute in based on each fixture's dependencies, their scope, and whether or not they are autouse.

When you have parameterized fixtures, only the fixtures that execute after the parameterized fixture will actually be affected by it (unless parameterization happens at the function scope level).

However, fixtures can have a non-deterministic place in this linearized order if they don't request other fixtures or other fixtures don't request them. It's basically a set of rules where each fixture says "I have to come after these fixtures". But without a fixture requesting other fixtures, or other fixtures requesting it, there's nothing tying it to a place in that linearized order.

Because of this, I'm guessing that, while the linearized order didn't technically change, pytest's awareness of what needs to be torn down when has been fixed, so now some of your fixtures are tearing down and being rebuilt where they weren't previously. In other words, if you ran pytest --setup-plan before this update, and after this update, they would have two different outputs, the latter of which, being much longer.

For a fix, I would leverage this linearization logic to figure out where exactly you want to insert your parameterization and then have fixtures request what's necessary to position your paremeterized fixture exactly where you want.

[frederic-peters]

Actually the setup-plan output has the same length, with just a little bit of ordering difference. However I switched my local tests from sqlite to postgresql to have detailed database logs and noticed the database was now being created and dropped for each test, while it was previously being reused (even without using --reuse-db from pytest-django). Running a subset of tests (19 individual tests using the database):

• 5.3.2, no reuse-db, 12.80s
• 5.3.2, reuse-db, 3.63s
• 5.3.3, no reuse-db,.168.61s
• 5.3.3, reuse-db, 12.84s

So yeah probably pytest was not previously tearing down the database properly, while it now is.

[blueyed]

@frederic-peters
Are you using db mainly/only or transactional_db also (more than a few)?
reuse-db should only make a difference for the global setup. 5.3.3 with no reuse-db looks like it might do it a few times more often.. ;)

Can you provide a diff of the setup-plans?

[frederic-peters]

@blueyed I am not using transactional_db at all.

diff of setup-plans, 5.3.2 vs 5.3.3 (curiously it had more differences yesterday, but probably I got confused between versions as I ran many checks, this one is double checked):

@@ -1,5 +1,5 @@
 ============================= test session starts ==============================
-platform linux -- Python 3.7.2rc1, pytest-5.3.2, py-1.8.0, pluggy-0.13.0 -- /home/fred/src/eo/venv3/bin/python3
+platform linux -- Python 3.7.2rc1, pytest-5.3.3, py-1.8.0, pluggy-0.13.0 -- /home/fred/src/eo/venv3/bin/python3
 cachedir: .pytest_cache
 django: settings: combo.settings (from env)
 rootdir: /home/fred/src/eo/combo
@@ -52,13 +52,13 @@
         TEARDOWN F _dj_autoclear_mailbox
       TEARDOWN C _django_setup_unittest
 tests/test_calendar.py::test_cell_rendering[anonymous] 
-SETUP    S django_db_use_migrations
-SETUP    S django_db_keepdb
 SETUP    S django_db_createdb
-SETUP    S django_db_modify_db_settings_tox_suffix
 SETUP    S django_db_modify_db_settings_xdist_suffix
+SETUP    S django_db_modify_db_settings_tox_suffix
 SETUP    S django_db_modify_db_settings_parallel_suffix (fixtures used: django_db_modify_db_settings_tox_suffix, django_db_modify_db_settings_xdist_suffix)
 SETUP    S django_db_modify_db_settings (fixtures used: django_db_modify_db_settings_parallel_suffix)
+SETUP    S django_db_use_migrations
+SETUP    S django_db_keepdb
 SETUP    S django_db_setup (fixtures used: django_db_blocker, django_db_createdb, django_db_keepdb, django_db_modify_db_settings, django_db_use_migrations, django_test_environment)
       SETUP    C _django_setup_unittest (fixtures used: django_db_blocker)
         SETUP    F _dj_autoclear_mailbox
@@ -6888,16 +6888,16 @@
         TEARDOWN F _dj_autoclear_mailbox
       TEARDOWN C _django_setup_unittest
 TEARDOWN S django_db_setup
-TEARDOWN S django_db_blocker
-TEARDOWN S django_test_environment
-TEARDOWN S _fail_for_invalid_template_variable
+TEARDOWN S django_db_keepdb
+TEARDOWN S django_db_use_migrations
 TEARDOWN S django_db_modify_db_settings
 TEARDOWN S django_db_modify_db_settings_parallel_suffix
-TEARDOWN S django_db_modify_db_settings_xdist_suffix
 TEARDOWN S django_db_modify_db_settings_tox_suffix
+TEARDOWN S django_db_modify_db_settings_xdist_suffix
 TEARDOWN S django_db_createdb
-TEARDOWN S django_db_keepdb
-TEARDOWN S django_db_use_migrations
+TEARDOWN S django_db_blocker
+TEARDOWN S django_test_environment
+TEARDOWN S _fail_for_invalid_template_variable

Hope it helps,