Perfromance drop in 7.0.2 comparing to 7.0.1

[detoyz]

Describe the bug
Our test suite execution time drastically increased during update of coverage version from 7.0.1 to 7.0.2

On 7.0.1

================================= 1209 passed, 2 warnings, 106 subtests passed in 102.66s (0:01:42) =================================

On 7.0.2(3)

================================= 1209 passed, 2 warnings, 106 subtests passed in 447.32s (0:07:27) =================================

To Reproduce

Execution command

coverage run -m pytest

Pytest run headers (for python version, pytest plugins)

platform linux -- Python 3.11.1, pytest-7.2.0, pluggy-1.0.0
configfile: pyproject.toml, testpaths: tests
plugins: asyncio-0.20.3, subtests-0.9.0, mock-3.10.0, bdd-6.1.1, Faker-15.3.4, respx-0.20.1
asyncio: mode=Mode.AUTO

Project/test context

Project is typical fastapi/starlette + sqlalchemy, written in async/await paradigm. Most tests are typical calls to web api request and assert api response. Unfortunately cannot share source code itself, but let me know if more info needed, maybe will be able to make a "demo" mini-project.

Coverage config

[tool.coverage.run]
branch = true
concurrency = [
    "greenlet",  # for async sqlalchemy
]
command_line = "-m pytest -v"
dynamic_context = "test_function"
source_pkgs = [
    "src",
]

[tool.coverage.report]
skip_empty = true
exclude_lines = [
    "pragma: no cover",
    "def __repr__",
    "if __name__ == .__main__."
]

[tool.coverage.html]
directory = "htmlcov"
show_contexts = true

Expected behavior
There probably shouldn't be such a huge performance drawback

Additional context
Initially I thought problem is connected to python3.11 and #1287, but after downgrading first to 6.X, performance degradation was gone. Than started to upgrade version by version, until had performance issue again.

I feel that problem can be connected to refactoring made in 7.0.2, as mentioned here:

Refactor: added many type annotations, including a number of refactorings. This should not affect outward behavior, but they were a bit invasive in some places, so keep your eyes peeled for oddities.

[nedbat]

The changes between 7.0.1 and 7.0.2 are very minimal, other than adding type annotations. Can you check that you have the C tracer installed with 7.0.2? The most likely cause of the slow down is using the Python tracer instead. The best information would be from adding this command to your CI: python -m coverage debug sys.

[nedbat]

My bad, it could be the changes between 7.0.1 and 7.0.2, but check the "debug sys" output before we go further.

[detoyz]

Output for 7.0.3

-- sys -------------------------------------------------------
               coverage_version: 7.0.3
                coverage_module: <project_root>/.venv/lib/python3.11/site-packages/coverage/__init__.py
                         tracer: -none-
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-
      plugins.context_switchers: -none-
              configs_attempted: .coveragerc
                                 setup.cfg
                                 tox.ini
                                 pyproject.toml
                   configs_read: <project_root>/pyproject.toml
                    config_file: <project_root>/pyproject.toml
                config_contents: b'...coverage sections presented in ticket description...'
                      data_file: -none-
                         python: 3.11.1 (main, Dec 23 2022, 11:47:36) [GCC 12.2.0]
                       platform: Linux-5.19.0-26-generic-x86_64-with-glibc2.36
                 implementation: CPython
                     executable: <project_root>/.venv/bin/python3
                   def_encoding: utf-8
                    fs_encoding: utf-8
                            pid: 182078
                            cwd: <project_root>
                           path: <project_root>
                                 /usr/local/lib/python311.zip
                                 /usr/local/lib/python3.11
                                 /usr/local/lib/python3.11/lib-dynload
                                 <project_root>/.venv/lib/python3.11/site-packages
                    environment: HOME = ***
                   command_line: <project_root>/.venv/lib/python3.11/site-packages/coverage/__main__.py debug sys
         sqlite3_sqlite_version: 3.39.3
             sqlite3_temp_store: 0
        sqlite3_compile_options: ATOMIC_INTRINSICS=1, COMPILER=gcc-12.2.0, DEFAULT_AUTOVACUUM,
                                 DEFAULT_CACHE_SIZE=-2000, DEFAULT_FILE_FORMAT=4,
                                 DEFAULT_JOURNAL_SIZE_LIMIT=-1, DEFAULT_MMAP_SIZE=0, DEFAULT_PAGE_SIZE=4096,
                                 DEFAULT_PCACHE_INITSZ=20, DEFAULT_RECURSIVE_TRIGGERS,
                                 DEFAULT_SECTOR_SIZE=4096, DEFAULT_SYNCHRONOUS=2,
                                 DEFAULT_WAL_AUTOCHECKPOINT=1000, DEFAULT_WAL_SYNCHRONOUS=2,
                                 DEFAULT_WORKER_THREADS=0, ENABLE_COLUMN_METADATA, ENABLE_DBSTAT_VTAB,
                                 ENABLE_FTS3, ENABLE_FTS3_PARENTHESIS, ENABLE_FTS3_TOKENIZER, ENABLE_FTS4,
                                 ENABLE_FTS5, ENABLE_LOAD_EXTENSION, ENABLE_MATH_FUNCTIONS,
                                 ENABLE_PREUPDATE_HOOK, ENABLE_RTREE, ENABLE_SESSION, ENABLE_STMTVTAB,
                                 ENABLE_UNLOCK_NOTIFY, ENABLE_UPDATE_DELETE_LIMIT, HAVE_ISNAN,
                                 LIKE_DOESNT_MATCH_BLOBS, MALLOC_SOFT_LIMIT=1024, MAX_ATTACHED=10,
                                 MAX_COLUMN=2000, MAX_COMPOUND_SELECT=500, MAX_DEFAULT_PAGE_SIZE=32768,
                                 MAX_EXPR_DEPTH=1000, MAX_FUNCTION_ARG=127, MAX_LENGTH=1000000000,
                                 MAX_LIKE_PATTERN_LENGTH=50000, MAX_MMAP_SIZE=0x7fff0000,
                                 MAX_PAGE_COUNT=1073741823, MAX_PAGE_SIZE=65536, MAX_SCHEMA_RETRY=25,
                                 MAX_SQL_LENGTH=1000000000, MAX_TRIGGER_DEPTH=1000,
                                 MAX_VARIABLE_NUMBER=250000, MAX_VDBE_OP=250000000, MAX_WORKER_THREADS=8,
                                 MUTEX_PTHREADS, OMIT_LOOKASIDE, SECURE_DELETE, SOUNDEX, SYSTEM_MALLOC,
                                 TEMP_STORE=1, THREADSAFE=1, USE_URI

Output for 7.0.1 produces same lines for CTracer:

-- sys -------------------------------------------------------
               coverage_version: 7.0.1
                coverage_module: <project_root>/.venv/lib/python3.11/site-packages/coverage/__init__.py
                         tracer: -none-
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-
      plugins.context_switchers: -none-
...

[nedbat]

Maybe it's the dynamic_context = "test_function" setting. I see a slight slowdown in 7.0.2 for that setting (18% slower, 93sec vs 79sec), but that is much different than the 4x slowdown that you are seeing.

Can you try running without that setting to see the time difference?

[detoyz]

Maybe it's the dynamic_context = "test_function" setting.

Yep, you're right. By removing dynamic_context = "test_function" execution time on 7.0.3 is even faster than on 7.0.1 with it enabled.

7.0.1 with dynamic_context = "test_function"

=========================================== 1213 passed, 2 warnings, 117 subtests passed in 205.85s (0:03:25) ============================================

7.0.3 with dynamic_context = "test_function"

=========================================== 1213 passed, 2 warnings, 117 subtests passed in 605.46s (0:10:05) ============================================

7.0.3 without dynamic_context

=========================================== 1213 passed, 2 warnings, 117 subtests passed in 123.15s (0:02:03) ============================================

(Note: I use different machine now to run suite, so results are not same as in description, but % of performance drops are about ~the same)

[detoyz]

@nedbat just FYI, we removed dynamic_context from CI, so for us issue can be considered as "resolved". Feel free to decide whether you want to investigate further & if needed update/close issue. I'll also be open to help you with further investigation if needed.

P.S. Thank you for amazing work you put in for this project. I truly enjoy using it and it made my life as a professional software engineer so much easier and happier 🎉

[nedbat]

My own testing seems to confirm that dynamic_context = "test_function" is typically about 20% slower with 7.0.2 than with 7.0.1. Can you say anything about what is unusual in your test suite that might give a clue about the extreme slow-down you saw? Another thing I see is "subtests", which I have never used. Can you give us a sneak peek at how you are using them?

[detoyz]

Sure!

subtests is a plugin for pytsest to basically have several asserts in one test that are considered as "sub-tests"

Example of our test using it

@pytest.mark.asyncio
async def test_validation_errors_rendered(
    self, api, subtests
):
    resp = await api.post(
        ...
    )

    assert resp.status == falcon.HTTP_422

    with subtests.test("expect title length error"):
        assert "at most 120 characters" in resp.text

    with subtests.test("expect url error"):
        assert "invalid or missing URL scheme" in resp.text

Regarding our test suite, as I mentioned in description, it's a typical web-api tests with only exception maybe that we utilizing all async-way (async web server, async db drivers, async redis, async httpx, etc)

Let me try to test more with/without dynamic context individual tests and came back to you, because I want to trim down what could lead 4x slowdown.

[detoyz]

@nedbat I could reproduce issue on a small demo project, that I published here -> https://github.com/detoyz/coverage_perf_702
All basic fixtures and setup I tried to mimic our own setup. Feel free to pull it out and try it yourself.

7.0.3 with dynamic_context = "test_function"

===== 50 passed in 7.81s ====

7.0.3 without dynamic_context = "test_function"

==== 50 passed in 2.81s ====

Potential cause of slowdown

As it seems to me, each SQLAlchemy awaitable (that internally by sqlalchemy opens a greenlet as far as I know) call in the code that is tested/executed - slows down execution under dynamic_context=true

So by increasing amount of calls here:

for x in range(50): 
    await conn.execute(
        sa.insert(Event).values({"name": f"some name {x}"})
    )

I could reproduce 3-4x slowdown.

So maybe it's something with related greenlet concurrency option? But my knowledge here is limited 😅

[nedbat]

Thanks for the test repo, I was able to use it with git bisect to find the problem. It was much more boring that any of us thought! It's fixed in commit b3b05bd.

         plugin._coverage_enabled = False
         disposition.trace = False

-    @functools.lru_cache(maxsize=0)
+    @functools.lru_cache(maxsize=None)
     def cached_mapped_file(self, filename: str) -> str:
         """A locally cached version of file names mapped through file_mapper."""
         return self.file_mapper(filename)

[nedbat]

This is now released as part of coverage 7.0.4.