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.