Setup times of long-running fixtures are attributed to first test

[sondrelg]

Description

The duration reporting in CallInfos (and consequently in TestReports) does not seem to work as expected.

From what I can tell, the setup times for fixtures that run before the test suite starts are attributed to the first test in the test suite. This means that if you have a long-running setup in a fixture, your first test is incorrectly attributed a longer duration just because it's the first test.

My actual issue stems from the setup-database fixture in pytest-django, which runs for 4-5 minutes before tests start. This setup time is attributed to my first test, which in turn prevents pytest-split from splitting my test suite evenly (based on stored durations).

If you point me in the right direction I'd be happy to contribute to resolving this 🙂

Reproducible example

This code sample

def test_something(testdir):
    testdir.makepyfile(
        """
        import pytest
        import time

        @pytest.fixture(autouse=True, scope="session")
        def slow_start():
            time.sleep(5)

        def test_something():
            time.sleep(1)

        def test_something_else():
            time.sleep(1)
        """
    )
    testdir.inline_run("--durations=6", "-vvv")

Outputs

============================= slowest 6 durations ==============================
5.01s setup    test_something.py::test_something
1.01s call     test_something.py::test_something
1.00s call     test_something.py::test_something_else
0.00s teardown test_something.py::test_something_else
0.00s teardown test_something.py::test_something
0.00s setup    test_something.py::test_something_else
============================== 2 passed in 7.03s ===============================

Environment

Don't think it's relevant here, but just in case: I'm using Pytest 6.2.4, python 3.9, with macos

[asottile]

I believe the output is correct -- notice how it has attributed those 5 seconds to setup for the test. how else would it be recorded?

[sondrelg]

Yeah I agree this is probably technically correct - and sorry my example above is actually not quite what I was hoping to convey.

This is what I was meaning to show

def test_something(testdir):
    testdir.makepyfile(
        """
        import pytest
        import time

        @pytest.fixture(autouse=True, scope="session")
        def slow_start():
            time.sleep(5)

        def test_something():
            time.sleep(1)

        def test_something_else():
            time.sleep(1)
        """
    )
    testdir.inline_run("--durations=6", "-vvv")

============================= slowest 6 durations ==============================
5.01s setup    test_something.py::test_something
1.01s call     test_something.py::test_something
1.00s call     test_something.py::test_something_else
0.00s teardown test_something.py::test_something_else
0.00s teardown test_something.py::test_something
0.00s setup    test_something.py::test_something_else
============================== 2 passed in 7.03s ===============================

It is correctly attributed to the setup time of the test, but what I was hoping to highlight is that it attributes it to the first test here, and not the second test, and the attribution happens somewhat arbitrarily right. If we remove test_something, the setup of the auto-used fixture will instead be attributed to test_something_else.

In my case I have a 400 second database-setup fixture running as the test-suite initializes, and that whole setup time is attributed to my first test 😅. This only really matters because we're trying to use durations to split the test suite into equal chunks, so these setup time attributions skew the split considerably.

---

So I'm not saying this is incorrect - technically it's probably correct; I just wanted to ask whether you think there exists a potential solution for this specific issue.

Totally understand if it's tricky, in which case I don't mind closing this - there are plenty of other ways for me to work around this 🙂

[asottile]

I'm not sure what you're expecting -- could you outline perhaps what you expect to see?

[sondrelg]

Simply (and naïvely) put, I would like fixtures whose lifetimes span the whole run to initialize in their own pre-test stage, so their setup times are not counted towards the runtime of the first test.

This might be an x y problem - I might not need what I just said - there might be a way to solve my issue another way, with metadata or more granular duration reporting. For example, if the test reporter had a breakdown of which fixtures took how much time in a test's setup I would also be able to piece together the durations I need.

Fundamentally I just need a way to figure out what the duration of a test would be if it wasn't the first one run.

---

But I also recognize that this is a very niche little issue, and there are other ways to get around this that won't involve changing pytest itself, so if you don't immediately see a way of achieving this, I'm happy to consider this issue fully explored and move on 🙂

Thanks for the quick responses btw 👏

[asottile]

so it sounds like you want fixture times to not be associated with the test that needs them, is this correct?

[RonnyPfannschmidt]

@asottile i believe the problem is that all the tests seem to need one big expensive fixture

that indeed messes up test timing, it would be nice to have a way to have complete testsuites request a particular fixture with a particular config and not count them as part of a single test

i also have a number of fixtures in a number of suites that really should be part of sessionstart, but we dont have a scope/way of doing that

[sondrelg]

Just in case you're waiting for me to confirm, yep this is exactly what I was trying to say 👏

[nicoddemus]

FTR https://github.com/mbkroese/pytest-timestamper might be of help. 👍

[simon-liebehenschel]

@sondrelg Move your expensive slow setup logic to the pytest_sessionstart() or pytest_collection_modifyitems().

I had the same problem, when I needed to see the first test execution time, but due to a slow fixture that time was about 60 seconds, instead of 5 seconds. I've removed my "session-scope" slow fixture, and moved that setup process to the pytest_sessionstart() inside the conftest.py file.

[sondrelg]

Thanks for the tip @AIGeneratedUsername 🙂 The fixture is unfortunately not my own - it's a library fixture (see here). With that in mind, would it still be possible to utilize pytest_sessionstart?

[simon-liebehenschel]

Thanks for the tip @AIGeneratedUsername slightly_smiling_face The fixture is unfortunately not my own - it's a library fixture (see here). With that in mind, would it still be possible to utilize pytest_sessionstart?

# any test file 

# Apply here any fixtures, which does not have `autouse=True`.
def test_trigger_all_session_fixtures():  # You may choose a different name.
    """
    An empty test which will run as first one to trigger slow fixtures.
    """
    pass

------------------------------------

# conftest.py

def pytest_collection_modifyitems(session: Session, config: Config, items: List[Item]) -> None:
    test_trigger_all_session_fixtures_index = None
    for i, item in enumerate(items):
        if "test_trigger_all_session_fixtures" in item.nodeid:
            test_trigger_all_session_fixtures_index = i
                break

    if test_trigger_all_session_fixtures_index:
        # Run as a first test
        items.insert(0, items.pop(test_trigger_all_session_fixtures_index))

Your first dummy test will trigger all "session-scope" explicitly passed fixtures (or with autouse=True). You do not care about its time, because it is an empty test. All other test will be with a real execution time.

[sondrelg]

That's very nice, but I'm not sure it would help me with my initial issue. My challenge was automatically registering all test times and splitting my test suite into smaller chunks to run on separate runner processes in a CI pipeline. Unless I'm mistaken I think I would still have the issue of test_trigger_all_session_fixtures being assigned the runtime of all my session-scoped fixtures, and it would still skew my splits, unfortunately.

I guess this would make it easier to filter out the noise though, so I'll see if I can implement this in my workaround 👍

[james-certn]

The best real world example of this for me is when running pytest with a Django project.

with no django migrations, 4 pytest process via pytest-xdist:

root@78bc5719ae48:/app# pytest -n 4 --durations=10 --nomigrations
================================================= test session starts ==================================================
platform linux -- Python 3.11.7, pytest-7.4.4, pluggy-1.4.0
django: version: 4.2.9, settings: project.settings (from env)
rootdir: /app
configfile: pytest.ini
plugins: django-4.7.0, cov-4.1.0, time-machine-2.13.0, xdist-3.5.0
4 workers [1263 items]
................................................................................................................ [  8%]
................................................................................................................ [ 17%]
................................................................................................................ [ 26%]
.......................s........................................................................................ [ 35%]
................................................................................................................ [ 44%]
.........................................................................................................s...... [ 53%]
.............................s................................................................................... [ 62%]
................................................................................................................ [ 71%]
................................................................................................................ [ 79%]
................................................................................................................ [ 88%]
................................................................................................................ [ 97%]
..............................                                                                                   [100%]

================================================= slowest 10 durations =================================================
3.09s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
0.82s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
0.49s setup    project/actions/authzero/api/tests/<redacted test module>.py::<redacted test function name>[401_UNAUTHORIZED]
0.49s setup    project/actions/tests/<redacted test module>.py::<redacted test function name>
0.49s setup    project/actions/tests/<redacted test module>.py::<redacted test function name>
0.49s setup    project/common/permissions/tests/<redacted test module>.py::<redacted test function name>
0.44s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
0.26s call     project/actions/tests/<redacted test module>.py::<redacted test function name>
0.22s call     project/interfaces/api/external/authzero/tests/<redacted test module>.py::<redacted test function name>
0.21s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
==================================== 1260 passed, 3 skipped, 16 warnings in 16.10s =====================================

with django migrations (pytest-django default), 4 pytest process via pytest-xdist

root@78bc5719ae48:/app# pytest -n 4 --durations=10
================================================= test session starts ==================================================
platform linux -- Python 3.11.7, pytest-7.4.4, pluggy-1.4.0
django: version: 4.2.9, settings: project.settings (from env)
rootdir: /app
configfile: pytest.ini
plugins: django-4.7.0, cov-4.1.0, time-machine-2.13.0, xdist-3.5.0
4 workers [1263 items]
................................................................................................................. [  8%]
................................................................................................................. [ 17%]
................................................................................................................ [ 26%]
......................s......................................................................................... [ 35%]
................................................................................................................. [ 44%]
......................................................................................................s......... [ 53%]
.......................s........................................................................................ [ 62%]
................................................................................................................ [ 71%]
................................................................................................................ [ 80%]
................................................................................................................ [ 88%]
................................................................................................................ [ 97%]
............................                                                                                     [100%]

================================================= slowest 10 durations =================================================
4.11s setup    project/actions/tests/<redacted test module>.py::<redacted test function name>
4.09s setup    project/common/permissions/tests/<redacted test module>.py::<redacted test function name>
4.08s setup    project/actions/tests/<redacted test module>.py::<redacted test function name>
4.04s setup    project/actions/authzero/api/tests/<redacted test module>.py::<redacted test function name>[401_UNAUTHORIZED]
3.11s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
0.82s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
0.44s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
0.24s call     project/actions/tests/<redacted test module>.py::<redacted test function name>
0.23s call     project/common/tests/<redacted test module>.py::<redacted test function name>[api:internal:case-management:generate-presigned-url]
0.21s call     project/interfaces/management_commands/management/tests/<redacted test module>.py::<redacted test function name>
==================================== 1260 passed, 3 skipped, 16 warnings in 19.72s =====================================

Note with Django migrations, there's a solid 4 seconds of test session-level activity happening (with our project's current migrations, will grow over time).

Random Idea 💡

I like the idea of separate session, class, function setup+call timings; it might be interesting to determine timings/durations of:

• session fixtures
• class fixtures
• function durations separated out into test setup (fixtures) and call timings

Could a separated reporting structure be supported?

[RonnyPfannschmidt]

with the current scope, the question/idea is to unclear to give a conclusive answer