From 8cfba065932e7ab0d9200299814a082b9ec41f5d Mon Sep 17 00:00:00 2001 From: Mike Fiedler Date: Fri, 24 Dec 2021 17:38:40 -0500 Subject: [PATCH] Initial commit Signed-off-by: Mike Fiedler --- .editorconfig | 13 +++ .github/FUNDING.yml | 3 + .github/workflows/pytest.yml | 40 +++++++ .gitignore | 153 +++++++++++++++++++++++++++ .pre-commit-config.yaml | 22 ++++ LICENSE | 22 ++++ README.md | 79 ++++++++++++++ pyproject.toml | 54 ++++++++++ pytest_execution_timer/__init__.py | 0 pytest_execution_timer/plugin.py | 110 +++++++++++++++++++ tests/__init__.py | 0 tests/conftest.py | 1 + tests/test_pytest_execution_timer.py | 53 ++++++++++ 13 files changed, 550 insertions(+) create mode 100644 .editorconfig create mode 100644 .github/FUNDING.yml create mode 100644 .github/workflows/pytest.yml create mode 100644 .gitignore create mode 100644 .pre-commit-config.yaml create mode 100644 LICENSE create mode 100644 README.md create mode 100644 pyproject.toml create mode 100644 pytest_execution_timer/__init__.py create mode 100644 pytest_execution_timer/plugin.py create mode 100644 tests/__init__.py create mode 100644 tests/conftest.py create mode 100644 tests/test_pytest_execution_timer.py diff --git a/.editorconfig b/.editorconfig new file mode 100644 index 0000000..8e60580 --- /dev/null +++ b/.editorconfig @@ -0,0 +1,13 @@ +# http://editorconfig.org + +root = true + +[*] +indent_style = space +insert_final_newline = true +trim_trailing_whitespace = true +end_of_line = lf +charset = utf-8 + +[*.py] +indent_size = 4 diff --git a/.github/FUNDING.yml b/.github/FUNDING.yml new file mode 100644 index 0000000..2eb4123 --- /dev/null +++ b/.github/FUNDING.yml @@ -0,0 +1,3 @@ +# These are supported funding model platforms + +github: miketheman diff --git a/.github/workflows/pytest.yml b/.github/workflows/pytest.yml new file mode 100644 index 0000000..95835da --- /dev/null +++ b/.github/workflows/pytest.yml @@ -0,0 +1,40 @@ +# This workflow will install Python dependencies, run tests and lint with a variety of Python versions +# For more information see: https://help.github.com/actions/language-and-framework-guides/using-python-with-github-actions + +name: Python Tests + +on: + # Trigger the workflow on push or pull request, + # but only for the main branch + push: + branches: + - main + pull_request: + branches: + - main + +jobs: + build: + + runs-on: ${{ matrix.os }} + strategy: + matrix: + os: + - macos-latest + - ubuntu-latest + - windows-latest + python-version: ["3.7", "3.8", "3.9", "3.10"] + + steps: + - uses: actions/checkout@v2 + - name: Set up Python ${{ matrix.python-version }} + uses: actions/setup-python@v2 + with: + python-version: ${{ matrix.python-version }} + - name: Install dependencies + run: | + python -m pip install --upgrade pip poetry + poetry install + - name: Test with coverage/pytest + run: | + poetry run coverage run -m pytest ; poetry run coverage report --show-missing diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..40f4139 --- /dev/null +++ b/.gitignore @@ -0,0 +1,153 @@ +# Byte-compiled / optimized / DLL files +__pycache__/ +*.py[cod] +*$py.class + +# C extensions +*.so + +# Distribution / packaging +.Python +build/ +develop-eggs/ +dist/ +downloads/ +eggs/ +.eggs/ +lib/ +lib64/ +parts/ +sdist/ +var/ +wheels/ +share/python-wheels/ +*.egg-info/ +.installed.cfg +*.egg +MANIFEST + +# PyInstaller +# Usually these files are written by a python script from a template +# before PyInstaller builds the exe, so as to inject date/other infos into it. +*.manifest +*.spec + +# Installer logs +pip-log.txt +pip-delete-this-directory.txt + +# Unit test / coverage reports +htmlcov/ +.tox/ +.nox/ +.coverage +.coverage.* +.cache +nosetests.xml +coverage.xml +*.cover +*.py,cover +.hypothesis/ +.pytest_cache/ +cover/ + +# Translations +*.mo +*.pot + +# Django stuff: +*.log +local_settings.py +db.sqlite3 +db.sqlite3-journal + +# Flask stuff: +instance/ +.webassets-cache + +# Scrapy stuff: +.scrapy + +# Sphinx documentation +docs/_build/ + +# PyBuilder +.pybuilder/ +target/ + +# Jupyter Notebook +.ipynb_checkpoints + +# IPython +profile_default/ +ipython_config.py + +# pyenv +# For a library or package, you might want to ignore these files since the code is +# intended to run in multiple environments; otherwise, check them in: +.python-version + +# pipenv +# According to pypa/pipenv#598, it is recommended to include Pipfile.lock in version control. +# However, in case of collaboration, if having platform-specific dependencies or dependencies +# having no cross-platform support, pipenv may install dependencies that don't work, or not +# install all needed dependencies. +#Pipfile.lock + +# poetry +# Similar to Pipfile.lock, it is generally recommended to include poetry.lock in version control. +# This is especially recommended for binary packages to ensure reproducibility, and is more +# commonly ignored for libraries. +# https://python-poetry.org/docs/basic-usage/#commit-your-poetrylock-file-to-version-control +poetry.lock + +# PEP 582; used by e.g. github.com/David-OConnor/pyflow +__pypackages__/ + +# Celery stuff +celerybeat-schedule +celerybeat.pid + +# SageMath parsed files +*.sage.py + +# Environments +.env +.envrc +.venv +env/ +venv/ +ENV/ +env.bak/ +venv.bak/ + +# Spyder project settings +.spyderproject +.spyproject + +# Rope project settings +.ropeproject + +# mkdocs documentation +/site + +# mypy +.mypy_cache/ +.dmypy.json +dmypy.json + +# Pyre type checker +.pyre/ + +# pytype static type analyzer +.pytype/ + +# Cython debug symbols +cython_debug/ + +# PyCharm +# JetBrains specific template is maintainted in a separate JetBrains.gitignore that can +# be found at https://github.com/github/gitignore/blob/main/Global/JetBrains.gitignore +# and can be added to the global gitignore or merged into this file. For a more nuclear +# option (not recommended) you can uncomment the following to ignore the entire idea folder. +.idea/ diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml new file mode 100644 index 0000000..a4a5fbd --- /dev/null +++ b/.pre-commit-config.yaml @@ -0,0 +1,22 @@ +# See https://pre-commit.com for more information +# See https://pre-commit.com/hooks.html for more hooks +repos: +- repo: https://github.com/pre-commit/pre-commit-hooks + rev: v4.0.1 + hooks: + - id: check-yaml + - id: check-added-large-files +- repo: https://github.com/editorconfig-checker/editorconfig-checker.python + rev: '2.4.0' + hooks: + - id: editorconfig-checker + alias: ec +- repo: https://github.com/pycqa/isort + rev: 5.10.1 + hooks: + - id: isort + name: isort (python) +- repo: https://github.com/psf/black + rev: 21.12b0 + hooks: + - id: black diff --git a/LICENSE b/LICENSE new file mode 100644 index 0000000..0a97a1b --- /dev/null +++ b/LICENSE @@ -0,0 +1,22 @@ + +The MIT License (MIT) + +Copyright (c) 2021 Mike Fiedler + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in +all copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +THE SOFTWARE. diff --git a/README.md b/README.md new file mode 100644 index 0000000..5dafef0 --- /dev/null +++ b/README.md @@ -0,0 +1,79 @@ +# pytest-execution-timer + +A plugin to use with Pytest to measure execution time of tests. + +Distinctly different from the `--durations` option of pytest, +this plugin measures specific pytest startup/collection phases. + +Leverages `pytest` hooks to measure execution time of phases. + +--- + +## Installation + +Requires: + +- Python 3.7 or later. +- Pytest 6.2 or later. + +Install the plugin with any approach for your project. + +Some examples: + +```shell +pip install pytest-execution-timer +``` + +```shell +poetry add --dev pytest-execution-timer +``` + +```shell +pipenv install --dev pytest-execution-timer +``` + +Or add it to your `requirements.txt` file. + +## Usage + +Enable the plugin with the `--execution-timer` option when running `pytest`: + +```console +$ pytest --execution-timer +... +Durations of pytest phases in seconds (min 100ms): +0.662 pytest_runtestloop +``` + +Control the threshold (default 100ms) by passing `--minimum-duration=`: + +```console +$ pytest --execution-timer --minimum-duration=1000 # 1 second +``` + +## Understanding the output + +The best ay to start is to compare the difference of the `pytest_runtestloop` duration +and the overall duration of the test run. Example: + +```console +Durations of pytest phases in seconds (min 100ms): +0.666 pytest_runtestloop +====== 4 passed in 0.68s ====== +``` + +In this example, there's not much lost between the test run and the `pytest_runtestloop` +meaning that the startup and collection phases are not taking too much time. + +If there's a larger difference in the timings, +look to other emitted phases to understand what's taking the most time. + +These can then be examined directly, +or use other tools like [profilers](https://docs.python.org/3/library/profile.html) +or [import timings](https://docs.python.org/3/using/cmdline.html#cmdoption-X). + +## License + +Distributed under the terms of the MIT license, +"pytest-execution-timer" is free and open source software. +See `LICENSE` for more information. diff --git a/pyproject.toml b/pyproject.toml new file mode 100644 index 0000000..3032279 --- /dev/null +++ b/pyproject.toml @@ -0,0 +1,54 @@ +[tool.poetry] +name = "pytest-execution-timer" +version = "0.1.0" +description = "A timer for the phases of Pytest's execution." +authors = ["Mike Fiedler "] +license = "MIT" +readme = "README.md" +homepage = "https://pypi.org/project/pytest-execution-timer/" +repository = "https://github.com/miketheman/pytest-execution-timer" +include = [ + { path = "LICENSE" }, + { path = "README.md" }, + { path = "tests", format = "sdist" }, +] +classifiers = [ + "Development Status :: 4 - Beta", + "Framework :: Pytest", + "Intended Audience :: Developers", + "Topic :: Software Development :: Testing", + "Programming Language :: Python", + "Programming Language :: Python :: 3.7", + "Programming Language :: Python :: 3.8", + "Programming Language :: Python :: 3.9", + "Programming Language :: Python :: 3.10", + "Programming Language :: Python :: Implementation :: CPython", + "Operating System :: OS Independent", + "License :: OSI Approved :: MIT License", +] + + +[tool.poetry.dependencies] +python = "^3.7" + +[tool.poetry.dev-dependencies] +pytest = "^6.2" +coverage = {extras = ["toml"], version = "^6.2"} + +[tool.poetry.plugins.pytest11] +execution_timer = "pytest_execution_timer.plugin" + +[tool.poetry.urls] +"Bug Tracker" = "https://github.com/miketheman/pytest-execution-timer/issues" + +[tool.coverage.run] +branch = true +source = ["pytest_execution_timer"] + +[tool.isort] +# https://black.readthedocs.io/en/stable/guides/using_black_with_other_tools.html#profilegcm +profile = "black" + +[build-system] +requires = ["poetry-core>=1.0.0"] +build-backend = "poetry.core.masonry.api" diff --git a/pytest_execution_timer/__init__.py b/pytest_execution_timer/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/pytest_execution_timer/plugin.py b/pytest_execution_timer/plugin.py new file mode 100644 index 0000000..747dc6c --- /dev/null +++ b/pytest_execution_timer/plugin.py @@ -0,0 +1,110 @@ +import time +import typing +from datetime import timedelta + +import pytest + + +class PytestExecutionTimer: + """ + A timer for the phases of Pytest's execution. + Distinctly different from `--durations=N` + in that this reports times spent **outside** tests. + + Not every hook is instrumented yet, + only the ones that I've observed causing slowdown. + More hook contributions are welcome! + """ + + durations: typing.Dict[str, float] = dict() + + # === Initialization Hooks === + # https://docs.pytest.org/en/stable/reference.html#initialization-hooks + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_sessionstart(self, session): + start = time.time() + yield + end = time.time() + self.durations["pytest_sessionstart"] = end - start + + # === Collection Hooks === + # https://docs.pytest.org/en/stable/reference.html#collection-hooks + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_collection(self, session): + start = time.time() + yield + end = time.time() + self.durations["pytest_collection"] = end - start + + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_collect_file(self, path, parent): + start = time.time() + yield + end = time.time() + self.durations[f"pytest_collect_file:{path}"] = end - start + + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_itemcollected(self, item): + start = time.time() + yield + end = time.time() + self.durations[f"pytest_itemcollected\t{item.name}"] = end - start + + # === Run Test Hooks === + # https://docs.pytest.org/en/stable/reference.html#test-running-runtest-hooks + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_runtestloop(self, session): + """Should mimic the output of the total test time reported by pytest. + May not be necessary.""" + start = time.time() + yield + end = time.time() + self.durations["pytest_runtestloop"] = end - start + + # === Reporting Hooks === + # https://docs.pytest.org/en/stable/reference.html#reporting-hooks + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_make_collect_report(self, collector): + """Despite being a Reporting hook, this fires during the Collection phase + and can find `test_*.py` level import slowdowns.""" + start = time.time() + yield + end = time.time() + self.durations[f"pytest_make_collect_report\t{collector.nodeid}"] = end - start + + def pytest_terminal_summary(self, terminalreporter, exitstatus, config): + """Where we emit our report.""" + min_duration = config.option.minimum_duration_in_ms + + terminalreporter.section("pytest-execution-timer") + terminalreporter.write_line( + f"Durations of pytest phases in seconds (min {min_duration}ms):" + ) + + for key, value in self.durations.items(): + # Only show items that took longer than the configured value + if value > timedelta(milliseconds=min_duration).total_seconds(): + terminalreporter.write_line(f"{value:.3f}\t{key}") + + +def pytest_addoption(parser): + group = parser.getgroup("execution_timer") + group.addoption( + "--execution-timer", + action="store_true", + dest="execution_timer", + help="Enable collection of pytest phase execution timing.", + ) + group.addoption( + "--minimum-duration", + action="store", + dest="minimum_duration_in_ms", + type=int, + default=100, + help="Minimum duration in milliseconds to show in the report.", + ) + + +def pytest_configure(config): + if config.option.execution_timer: + config.pluginmanager.register(PytestExecutionTimer()) diff --git a/tests/__init__.py b/tests/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/tests/conftest.py b/tests/conftest.py new file mode 100644 index 0000000..694d7d5 --- /dev/null +++ b/tests/conftest.py @@ -0,0 +1 @@ +pytest_plugins = "pytester" diff --git a/tests/test_pytest_execution_timer.py b/tests/test_pytest_execution_timer.py new file mode 100644 index 0000000..46ac491 --- /dev/null +++ b/tests/test_pytest_execution_timer.py @@ -0,0 +1,53 @@ +import pytest + + +def test_shows_help_when_enabled(pytester): + result = pytester.runpytest("--help") + assert result.ret == 0 + result.stdout.fnmatch_lines( + ["*execution_timer:*", "*--execution-timer*", "*--minimum-duration*"] + ) + + +def test_does_not_emit_when_not_enabled(pytester): + pytester.makepyfile( + """ + import time + + def test_execution(): + time.sleep(0.2) + """ + ) + result = pytester.runpytest() + assert result.ret == 0 + # Confirm that the plugin output is not present + with pytest.raises(pytest.fail.Exception): + result.stdout.fnmatch_lines(["*Durations*", "*0.*pytest_runtestloop*"]) + + +def test_omits_duration_when_enabled(pytester): + pytester.makepyfile( + """ + import time + + def test_execution(): + time.sleep(0.2) + """ + ) + result = pytester.runpytest("--execution-timer") + assert result.ret == 0 + result.stdout.fnmatch_lines(["*Durations*", "*0.*pytest_runtestloop*"]) + + +def test_configured_duration_is_used(pytester): + pytester.makepyfile( + """ + import time + + def test_execution(): + time.sleep(0.1) + """ + ) + result = pytester.runpytest("--execution-timer", "--minimum-duration=100") + assert result.ret == 0 + result.stdout.fnmatch_lines(["*Durations*", "*0.*pytest_runtestloop*"])