Recording Test Duration with Python pytest

Recently, I read an article titled Timing Tests in Python for Fun and Profit, which is well worth a read. The article discusses how to find test cases that need speed improvement by recording their execution time (and in the process, you might also discover code with poor performance).

However, I often use pytest, so I spent some extra time finding out how to achieve the same in pytest.

The environment used in this article is:

- Python 3.5
- pytest 3.0.4

The structure of the test folder is:

├── conftest.py
└── module_example
    ├── __init__.py
    └── test_example.py

Actually, pytest already records the execution time for each test case, dividing it into three sections: setup, call, and teardown. We won’t delve into setup and teardown here; interested readers can go through the unittest documentation to learn about these terms. This post focuses directly on the call execution time, which is the actual time taken to run a test case.

By default, pytest doesn’t display the time for each test separately. To achieve this, you can use a pytest hook - pytest_terminal_summary. This hook can be used to retrieve a report of each test after all tests have completed and then print out their execution times individually.

The code is quite simple. You just need to implement the pytest_terminal_summary hook in conftest.py:

# conftest.py
def pytest_terminal_summary(terminalreporter, exitstatus):
    # Gather each report
    reports = []
    for replist in terminalreporter.stats.values():
        for rep in replist:
            if hasattr(rep, 'duration'):
                reports.append(rep)

    if not reports:
        return

    # Sort by execution time (duration) in descending order
    reports.sort(key=lambda x: x.duration)
    reports.reverse()

    terminalreporter.write_sep("=", "test durations")
    for rep in reports:
        # Focus only on the call stage
        if rep.when != 'call':
            continue

        nodeid = rep.nodeid.replace("::()::", "::")
        terminalreporter.write_line("%02.2fs %s" % (rep.duration, nodeid))

Execution result (the test durations section at the bottom):

▶ py.test .
============= test session starts =============
platform darwin -- Python 3.5.2, pytest-3.0.4, py-1.4.31, pluggy-0.4.0
rootdir: /home/example/tests, inifile:
collected 2 items

module_example/test_example.py ..

=============== test durations ================
5.00s module_example/test_example.py::test_abc
0.00s module_example/test_example.py::test_def
========== 2 passed in 5.02 seconds ===========

Additionally, to see what attributes are available in each report, check out TestReport.

That’s all.

Happy coding!

• http://doc.pytest.org/en/latest/_modules/_pytest/runner.html