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?

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.