Poor performance in Python 3.12
asmeurer opened this issue · 12 comments
Describe the bug
I recently added a Python 3.12-dev build to a project where I enable coverage on all the CI test runs, and the 3.12 build has consistently been taking nearly twice a long to complete as the 3.8-3.11 builds.
I made a test PR disabling coverage and the issue went away. Obviously without coverage the tests run faster, but the point is that the different Python versions all ran in about the same time.
Compare some builds (with coverage):
https://github.com/Quansight-Labs/ndindex/actions/runs/5734923621/usage?pr=155
https://github.com/Quansight-Labs/ndindex/actions/runs/5734722635/usage
A build with coverage disabled:
https://github.com/Quansight-Labs/ndindex/actions/runs/5765483809/usage?pr=161
To Reproduce
I haven't yet tried to install Python 3.12 to see if I can reproduce this locally, but the performance hit is pretty consistent on CI (you can see it on pretty much every recent build in Quansight-Labs/ndindex#155 for example).
Happy to provide more info, and try to repro locally if you can suggest an easy way to install a Python 3.12 environment. The package in question is pure Python, but the tests depend heavily on both numpy (I've been installing 3.12-compatible dev wheels from https://pypi.anaconda.org/scientific-python-nightly-wheels/simple) and hypothesis.
I mostly just wanted to make sure was on your radar since I didn't see any other issues about it.
The first thing to check is whether 3.12 has the C extension available. coverage --help will show:
% coverage --help
Coverage.py, version 7.2.7 with C extension
Measure, collect, and report on code coverage in Python programs.
or:
% coverage debug sys
-- sys -------------------------------------------------------
coverage_version: 7.2.7
coverage_module: /usr/local/virtualenvs/tmp-4637fade7458920/lib/python3.10/site-packages/coverage/__init__.py
tracer: -none-
CTracer: available
It apparently does: https://github.com/Quansight-Labs/ndindex/actions/runs/5766363872/job/15634144314?pr=161#step:5:30. It looks like there are 3.12 manylinux builds on pypi https://pypi.org/project/coverage/#files, so it is grabbing that.
Here's coverage debug sys:
+ coverage debug sys
-- sys -------------------------------------------------------
coverage_version: 7.2.7
coverage_module: /opt/hostedtoolcache/Python/3.12.0-beta.4/x64/lib/python3.12/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: /home/runner/work/ndindex/ndindex/.coveragerc
config_file: /home/runner/work/ndindex/ndindex/.coveragerc
config_contents: b'[run]\nomit =\n ndindex/_version.py\n ndindex/tests/doctest.py\n ndindex/tests/test_no_dependencies.py\n\n[report]\nexclude_lines =\n raise NotImplementedError\n pragma: no cover\n raise AssertionError\n except NotImplementedError:\n\n# Require full coverage. Lines that cannot be covered can be added as regexes\n# above, or excluded using # pragma: no cover\nfail_under = 100\n'
data_file: -none-
python: 3.12.0b4 (main, Jul 12 2023, 06:20:24) [GCC 11.3.0]
platform: Linux-5.15.0-1042-azure-x86_64-with-glibc2.35
implementation: CPython
executable: /opt/hostedtoolcache/Python/3.12.0-beta.4/x64/bin/python
def_encoding: utf-8
fs_encoding: utf-8
pid: 1789
cwd: /home/runner/work/ndindex/ndindex
path: /opt/hostedtoolcache/Python/3.12.0-beta.4/x64/bin
/opt/hostedtoolcache/Python/3.12.0-beta.4/x64/lib/python312.zip
/opt/hostedtoolcache/Python/3.12.0-beta.4/x64/lib/python3.12
/opt/hostedtoolcache/Python/3.12.0-beta.4/x64/lib/python3.12/lib-dynload
/opt/hostedtoolcache/Python/3.12.0-beta.4/x64/lib/python3.12/site-packages
environment: HOME = /home/runner
command_line: /opt/hostedtoolcache/Python/3.12.0-beta.4/x64/bin/coverage debug sys
sqlite3_sqlite_version: 3.37.2
sqlite3_temp_store: 0
sqlite3_compile_options: ATOMIC_INTRINSICS=1, COMPILER=gcc-11.3.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_JSON1, 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=[50](https://github.com/Quansight-Labs/ndindex/actions/runs/5766385439/job/15634216577?pr=161#step:5:51)0, 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=65[53](https://github.com/Quansight-Labs/ndindex/actions/runs/5766385439/job/15634216577?pr=161#step:5:54)6, 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
(from https://github.com/Quansight-Labs/ndindex/actions/runs/5766385439/job/15634216577?pr=161#step:5:48)
This is a mystery. I forked your repo (https://github.com/nedbat/ndindex) and hacked away at it. Now I have a file (justdoit.py) that sets a do-nothing trace function, and runs one of your tests: https://github.com/nedbat/ndindex/actions/runs/5767689409. On 3.11, it takes 14sec. On 3.12, it takes 43sec. I don't know why. We could toss this over to CPython to diagnose. They will probably want to take a look.
I've reported this in CPython: python/cpython#107674
On 3.11, it takes 14sec. On 3.12, it takes 43sec. I don't know why. We could toss this over to CPython to diagnose. They will probably want to take a look.
This is with the C extension? At CPython they had a look and didn't do anything for 3.12.0. There are some hopes that coveragepy will switch to the new monitoring API for 3.12 but I didn't find any trace supporting that hope here in coveragepy repo. Is there hope :)? python/cpython#107841 (comment)
I've pinged the core dev on the CPython issue. I have started on code to use the new PEP 669 monitoring, but I haven't made much progress on it. I'd welcome help.
For anyone else still struggling with this and who missed the changelog:
coverage 7.4.0 includes experimental support for PEP 669 that can be enabled with COVERAGE_CORE=sysmon environment variable, which already speeds up line coverage.
Thanks for the tip. This would be a lot easier to use if that variable were just ignored for Python 3.11 and lower. Right now, setting it causes those versions to raise an exception.
This would be a lot easier to use if that variable were just ignored for Python 3.11 and lower. Right now, setting it causes those versions to raise an exception.
Yes, I've gotten that feedback, and there's a PR: #1747. I'll figure out how to make that right soon.
This flag has indeed made the coverage runs for 3.12 way faster. They now run in about the same amount of time as when coverage is disabled! https://github.com/Quansight-Labs/ndindex/actions/runs/7892990262/usage
Here's coverage disabled completely for comparison:
Contrary to what others reported, the COVERAGE_CORE=sysmon option seems to degrade performance even further when running the scikit-learn tests with coverage enabled on CPython 3.12 (at least under Linux):