Performance regression in 6.4.3 when using dynamic_context

[mkniewallner]

Describe the bug
While trying to bump the version of coverage to 6.4.3+ on a project using dynamic_context = test_function, I've noticed an important duration increase when running the tests through coverage, as the CI job went from ~15 minutes to ~30 minutes.

To Reproduce
The bug was reproduced using Python 3.10.9, and the problem seems to appear in all versions of coverage above 6.4.3.

I managed to reproduce the issue on django project, by forking the repository and creating https://github.com/mkniewallner/django/pull/2/files to add dynamic_context = test_function and run the tests through coverage with the following 3 versions (multiple times, to avoid a possible randomness):

• 6.4.2: 16m48s
• 6.4.3: 22m8s
• 7.0.5: 22m4s

I've also created a minimal project to more easily debug the issue: https://github.com/mkniewallner/showcase-coverage-dynamic-context-perf/.

It's important to note that I was only able to reproduce the performance regression when dynamic_context is set to test_function. If disabled, the performance between the 3 versions is about the same.

Output of coverage debug sys

-- sys -------------------------------------------------------
               coverage_version: 6.4.3
                coverage_module: <REDACTED>/.pyenv/versions/3.10.9/envs/showcase-dynamic-context-perf/lib/python3.10/site-packages/coverage/__init__.py
                         tracer: -none-
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-
      plugins.context_switchers: -none-
              configs_attempted: .coveragerc
                   configs_read: <REDACTED>/showcase_dynamic_context_perf/.coveragerc
                    config_file: <REDACTED>/showcase_dynamic_context_perf/.coveragerc
                config_contents: b'[run]\nsource = a_project\ndynamic_context = test_function\nrelative_files = True\nbranch = True\n'
                      data_file: -none-
                         python: 3.10.9 (main, Dec 13 2022, 10:47:28) [Clang 14.0.0 (clang-1400.0.29.202)]
                       platform: macOS-13.0.1-arm64-arm-64bit
                 implementation: CPython
                     executable: <REDACTED>/.pyenv/versions/3.10.9/envs/showcase-dynamic-context-perf/bin/python3.10
                   def_encoding: utf-8
                    fs_encoding: utf-8
                            pid: 15007
                            cwd: <REDACTED>/showcase_dynamic_context_perf
                           path: <REDACTED>/.pyenv/versions/3.10.9/envs/showcase-dynamic-context-perf/bin
                                 <REDACTED>/.pyenv/versions/3.10.9/lib/python310.zip
                                 <REDACTED>/.pyenv/versions/3.10.9/lib/python3.10
                                 <REDACTED>/.pyenv/versions/3.10.9/lib/python3.10/lib-dynload
                                 <REDACTED>/.pyenv/versions/3.10.9/envs/showcase-dynamic-context-perf/lib/python3.10/site-packages
                    environment: HOME = <REDACTED>
                                 PYENV_ACTIVATE_SHELL = 1
                                 PYENV_DIR = <REDACTED>/showcase_dynamic_context_perf
                                 PYENV_HOOK_PATH = <REDACTED>/.pyenv/pyenv.d:/opt/homebrew/Cellar/pyenv/2.3.11/pyenv.d:/opt/homebrew/etc/pyenv.d:/etc/pyenv.d:/usr/lib/pyenv/hooks
                                 PYENV_ROOT = <REDACTED>/.pyenv
                                 PYENV_SHELL = fish
                                 PYENV_VERSION = showcase-dynamic-context-perf
                                 PYENV_VIRTUAL_ENV = <REDACTED>/.pyenv/versions/3.10.9/envs/showcase-dynamic-context-perf
                   command_line: <REDACTED>/.pyenv/versions/showcase-dynamic-context-perf/bin/coverage debug sys
                sqlite3_version: 2.6.0
         sqlite3_sqlite_version: 3.39.4
             sqlite3_temp_store: 0
        sqlite3_compile_options: ATOMIC_INTRINSICS=1, BUG_COMPATIBLE_20160819, CCCRYPT256,
                                 COMPILER=clang-14.0.0, DEFAULT_AUTOVACUUM, DEFAULT_CACHE_SIZE=2000,
                                 DEFAULT_CKPTFULLFSYNC, DEFAULT_FILE_FORMAT=4,
                                 DEFAULT_JOURNAL_SIZE_LIMIT=32768, DEFAULT_LOOKASIDE=1200,102,
                                 DEFAULT_MEMSTATUS=0, 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=1,
                                 DEFAULT_WORKER_THREADS=0, ENABLE_API_ARMOR, ENABLE_BYTECODE_VTAB,
                                 ENABLE_COLUMN_METADATA, ENABLE_DBSTAT_VTAB, ENABLE_FTS3,
                                 ENABLE_FTS3_PARENTHESIS, ENABLE_FTS3_TOKENIZER, ENABLE_FTS4, ENABLE_FTS5,
                                 ENABLE_LOCKING_STYLE=1, ENABLE_NORMALIZE, ENABLE_PREUPDATE_HOOK,
                                 ENABLE_RTREE, ENABLE_SESSION, ENABLE_SNAPSHOT, ENABLE_SQLLOG,
                                 ENABLE_STMT_SCANSTATUS, ENABLE_UNKNOWN_SQL_FUNCTION,
                                 ENABLE_UPDATE_DELETE_LIMIT, HAS_CODEC_RESTRICTED, HAVE_ISNAN,
                                 MALLOC_SOFT_LIMIT=1024, MAX_ATTACHED=10, MAX_COLUMN=2000,
                                 MAX_COMPOUND_SELECT=500, MAX_DEFAULT_PAGE_SIZE=8192, MAX_EXPR_DEPTH=1000,
                                 MAX_FUNCTION_ARG=127, MAX_LENGTH=2147483645, MAX_LIKE_PATTERN_LENGTH=50000,
                                 MAX_MMAP_SIZE=1073741824, MAX_PAGE_COUNT=1073741823, MAX_PAGE_SIZE=65536,
                                 MAX_SQL_LENGTH=1000000000, MAX_TRIGGER_DEPTH=1000,
                                 MAX_VARIABLE_NUMBER=500000, MAX_VDBE_OP=250000000, MAX_WORKER_THREADS=8,
                                 MUTEX_UNFAIR, OMIT_AUTORESET, OMIT_LOAD_EXTENSION, STMTJRNL_SPILL=131072,
                                 SYSTEM_MALLOC, TEMP_STORE=1, THREADSAFE=2, USE_URI

Output of pip freeze

coverage==6.4.3

I've run coverage on the project with the following command:

coverage run --debug sql -m unittest discover

and noticed that the output was different between 6.4.2 and 6.4.3/7.0.5.

Output for 6.4.2

Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select version from coverage_schema'
EXCEPTION from execute: no such table: coverage_schema
Executing script with 1995 chars: 'CREATE TABLE coverage_schema (\n    -- One row,...foreign key (file_id) references file (id)\n);\n'
Executing 'insert into coverage_schema (version) values (?)' with (7,)
Executing many 'insert or ignore into meta (key, value) values (?, ?)' with 3 rows
Executing "select value from meta where key = 'has_arcs'"
Executing 'select id, path from file'
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'insert or ignore into meta (key, value) values (?, ?)' with ('has_arcs', '1')
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing 'insert into context (context) values (?)' with ('',)
Executing 'insert or replace into file (path) values (?)' with ('a_project/__init__.py',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 2 rows
Executing 'insert or replace into file (path) values (?)' with ('a_project/foo.py',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 2 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('tests.test_foo.FooTestCase.test_foo',)
Executing 'insert into context (context) values (?)' with ('tests.test_foo.FooTestCase.test_foo',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 2 rows
.
----------------------------------------------------------------------
Ran 1 test in 0.005s

OK
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select * from file limit 1'
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'

Output for 6.4.3/7.0.5

Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select version from coverage_schema'
EXCEPTION from execute: no such table: coverage_schema
Executing script with 1995 chars: 'CREATE TABLE coverage_schema (\n    -- One row,...foreign key (file_id) references file (id)\n);\n'
Executing 'insert into coverage_schema (version) values (?)' with (7,)
Executing many 'insert or ignore into meta (key, value) values (?, ?)' with 3 rows
Executing "select value from meta where key = 'has_arcs'"
Executing 'select id, path from file'
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'insert or ignore into meta (key, value) values (?, ?)' with ('has_arcs', '1')
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing 'insert into context (context) values (?)' with ('',)
Executing 'insert or replace into file (path) values (?)' with ('a_project/__init__.py',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 2 rows
Executing 'insert or replace into file (path) values (?)' with ('a_project/foo.py',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 2 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('unittest.case._Outcome.testPartExecutor',)
Executing 'insert into context (context) values (?)' with ('unittest.case._Outcome.testPartExecutor',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('unittest.case._Outcome.testPartExecutor',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('unittest.case._Outcome.testPartExecutor',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('tests.test_foo.FooTestCase.test_foo',)
Executing 'insert into context (context) values (?)' with ('tests.test_foo.FooTestCase.test_foo',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 2 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('unittest.case._Outcome.testPartExecutor',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('unittest.case._Outcome.testPartExecutor',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('unittest.case._Outcome.testPartExecutor',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
.
----------------------------------------------------------------------
Ran 1 test in 0.007s

OK
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select id from context where context = ?' with ('',)
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Executing many 'insert or ignore into arc (file_id, context_id, fromno, tono) values (?, ?, ?, ?)' with 0 rows
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'
Executing 'select * from file limit 1'
Connecting to '<REDACTED>/showcase_dynamic_context_perf/.coverage'
Executing 'pragma journal_mode=off'
Executing 'pragma synchronous=off'

We can notice a lot more SQL queries (both selects and inserts attempts with 0 rows) in 6.4.3, that we don't have on 6.4.2.

Looking through the changes between 6.4.3 and 6.4.2, I managed to track down that this is probably caused by f54428f from #1347.

To reproduce:

git clone [email protected]:mkniewallner/showcase-coverage-dynamic-context-perf.git
cd showcase-coverage-dynamic-context-perf

# Create a virtual environment first.

# https://github.com/nedbat/coveragepy/commit/f54428fb8dfe98aacecc0b66e3c1ca2071ce1834
pip install git+https://github.com/nedbat/coveragepy@f54428fb8dfe98aacecc0b66e3c1ca2071ce1834 --force-reinstall
coverage run --debug sql -m unittest discover

# https://github.com/nedbat/coveragepy/commit/6ffb2c331d19d42580bfdaf0c44f5441b9ceb419, previous commit from the one above.
pip install git+https://github.com/nedbat/coveragepy@6ffb2c331d19d42580bfdaf0c44f5441b9ceb419 --force-reinstall
coverage run --debug sql -m unittest discover

Running the coverage command with the first commit gives the same output as the one above with 6.4.3, while running it with the second commit gives the same one as 6.4.2.

Doing the same on the project where the duration increase was originally noticed also shows that the duration is back to normal with the second commit, while it takes 2x more time with the first commit.

Expected behavior
No performance regression between 6.4.2 and 6.4.3.

Additional context
I'd be happy to add additional information if what is provided is not enough.

[nedbat]

... if what is provided is not enough.

LOL, this is the most complete bug report I've ever received! You've done plenty, thanks. Now I have to try to understand why it's a good thing for Cython, and what to do about it.

[nedbat]

This is fixed in commit 4cc3292.

[nedbat]

This is now released as part of coverage 7.1.0.

[abo-abo]

Hi @nedbat,

We're having the same performance issue as the requester: the CI run has increased from ~5min to
~10min when we use coverage>=6.4.3. I've bisected it (just like the requester) to
f54428f. When I revert this commit on top of 7.2.3, the run times return to normal.

Should we reopen this issue? @mkniewallner was your performance problem resolved?

[nedbat]

#1586 seems related.

[abo-abo]

@nedbat Good catch! It's totally related. We went from 9.2M .coverage file to a 121M .coverage file. This is just for 1/8 runners. We later combine the 8 runs, so the final file would be really huge.