Pytest: Finding when each test started and ended

Question

I have a complex Django-Pytest test suite with lots of tests that are running in parallel processes. I'd like to see the exact timepoint at which each test started and ended. How can I get that information out of Pytest?

Wakerly

Answer 1

The start/stop timestamps for each call phase are stored in the CallInfo objects. However, accessing those for reporting is not very convenient, so it's best to store both timestamps in the report objects. Put the following code in a conftest.py file in your project/test root dir:

import pytest


@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_makereport(item, call):
    outcome = yield
    report = outcome.get_result()
    report.start = call.start
    report.stop = call.stop

Now that you have each report enhanced with start/stop times, process them the way you need to, for example by printing them in a custom section after the test execution. Enhance your conftest.py file with:

def pytest_terminal_summary(terminalreporter):
    terminalreporter.ensure_newline()
    terminalreporter.section('start/stop times', sep='-', bold=True)
    for stat in terminalreporter.stats.values():
        for report in stat:
            if report.when == 'call':
                start = datetime.fromtimestamp(report.start)
                stop = datetime.fromtimestamp(report.stop)
                terminalreporter.write_line(f'{report.nodeid:20}: {start:%Y-%m-%d %H:%M:%S} - {stop:%Y-%m-%d %H:%M:%S}')

A test execution of sample tests

def test_spam():
    time.sleep(1)


def test_eggs():
    time.sleep(2)

now yields:

test_spam.py ..                                                         [100%]

------------------------------ start/stop times -------------------------------
test_spam.py::test_spam: 2020-04-26 13:29:05 - 2020-04-26 13:29:06
test_spam.py::test_eggs: 2020-04-26 13:29:06 - 2020-04-26 13:29:08
============================== 2 passed in 3.03s ==============================

Notice that in the above pytest_terminal_summary hookimpl example, I only print the time of the call phase (execution times of the test function). If you want to see or include the timestamps of the test setup/teardown phases, filter terminalreporter.stats by report objects with report.when == 'setup'/report.when == 'teardown', respectively.

Pervade

is there any way to take the timeout for workers, i am using extensively using -n=10 , but my setup is taking a lot time of in here while distributing tests to workers. i want to debug further and see why it is delayed. Actual test execution is faster but load schduling is taking a lot of time . – Facula

When I add these two functions to my conftest.py and run pytest -v tests/, I get AttributeError: 'WarningReport' object has no attribute 'when' – Mediterranean

@SergeyZakharov IIRC pytest has no WarningReports. Those may be part of some plugin installed in your environment - in this case, it is not compliant with pytest.reports.BaseReport. You can get around it by doing smith like if getattr(report, 'when', None) == 'call': … – Pervade

Answer 2

This can be accomplished with an implicit fixture and the request fixture:

import pytest
import logging
log = logging.getLogger(__name__)
@pytest.fixture(autouse=True, scope='function')
def implicit_fixture(request):
    log.info(f"{request.node.cls} {request.node.name} begin.")
    yield
    log.info(f"{request.node.cls} {request.node.name} end.")

Augur