Closed
Description
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):
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_URIOutput of pip freeze
coverage==6.4.3I've run coverage on the project with the following command:
coverage run --debug sql -m unittest discoverand 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 git@github.com: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 discoverRunning 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.