coveragepy
coveragepy copied to clipboard
nedbat
Performance of coverage.py under 3.11
We* are concerned about what 3.11 is doing to the performance of coverage.py.
This is more of a CPython issue, but I'm hoping that the coverage.py folks can provide some meaningful data about performance.
CPython issue: https://bugs.python.org/issue45923
* @markshannon and @pablogsal
Can you say more about why you are concerned? Has something slowed down? What is it you would like me to do?
Can you say more about why you are concerned? Has something slowed down? What is it you would like me to do?
Check https://github.com/python/cpython/pull/29729#discussion_r756146975 for instance
What is it you would like me to do?
Nothing for now, but thanks for the offer.
I'm seeing ~major~ performance regression with coverage and Python 3.11.0b1 (compared to 3.10). Tests run on MacOS with coverage 6.3.3.
Project 1 - mostly unit tests
| Python version | Time | With Coverage |
|---|---|---|
| 3.10.4 | 61s | 109s |
| 3.11.0b1 | 44s (-28%) | 171s (+157%) |
Project 2 - mostly functional tests
| Python version | Time | With Coverage |
|---|---|---|
| 3.10.4 | 101s | 151s |
| 3.11.0b1 | 90s (-11%) | ~800s (+529%)~ 316s (+209%) |
~For P1 I also have a CI run on ubuntu with an even bigger difference. Without 24s, with coverage: 391s. (3.11.0b1)~
Edit: Some test environments had 6.3.2 installed in which the CTracer was unavailable. Updated run times.
@cdce8p The most likely cause of a slowdown that large is using the Python tracer instead of the CTracer. Can you add COVERAGE_DEBUG=sys into the environment variables when you run coverage and show the output you get?
@cdce8p The most likely cause of a slowdown that large is using the Python tracer instead of the CTracer. Can you add
COVERAGE_DEBUG=sysinto the environment variables when you run coverage and show the output you get?
Thanks for the quick reply! I checked all environments and it looks like some were still using 6.3.2, not 6.3.3 and thus the CTracer was unavailable. In particular the two outliers. I will include the debug logs from the CI runner below if you still want to take a look.
The times are much better now, however that doesn't resolve all issues. For the mostly unit test suit, I'm still seeing a ~34% (94s -> 126s) slowdown. Whereas the functional tests now need 316s (from 151s), so around ~2x the time of 3.10.4.
> Debug log (old) - with 6.3.2
-- sys -------------------------------------------------------
coverage_version: 6.3.2
coverage_module: /home/runner/work/astroid/astroid/venv/lib/python3.11/site-packages/coverage/__init__.py
tracer: -none-
CTracer: unavailable
plugins.file_tracers: -none-
plugins.configurers: -none-
plugins.context_switchers: -none-
configs_attempted: .coveragerc
configs_read: /home/runner/work/astroid/astroid/.coveragerc
config_file: /home/runner/work/astroid/astroid/.coveragerc
config_contents: b'[paths]\nsource =\n astroid\n\n[report]\ninclude =\n astroid/*\nomit =\n */tests/*\nexclude_lines =\n # Re-enable default pragma\n pragma: no cover\n\n # Debug-only code\n def __repr__\n\n # Type checking code not executed during pytest runs\n if TYPE_CHECKING:\n @overload\n'
data_file: -none-
python: 3.11.0b1 (main, May 8 2022, 15:20:32) [GCC 9.4.0]
platform: Linux-5.13.0-1022-azure-x86_64-with-glibc2.31
implementation: CPython
executable: /home/runner/work/astroid/astroid/venv/bin/python
def_encoding: utf-8
fs_encoding: utf-8
pid: 1655
cwd: /home/runner/work/astroid/astroid
path: /home/runner/work/astroid/astroid/venv/bin
/opt/hostedtoolcache/Python/3.11.0-beta.1/x64/lib/python311.zip
/opt/hostedtoolcache/Python/3.11.0-beta.1/x64/lib/python3.11
/opt/hostedtoolcache/Python/3.11.0-beta.1/x64/lib/python3.11/lib-dynload
/home/runner/work/astroid/astroid/venv/lib/python3.11/site-packages
/home/runner/work/astroid/astroid
environment: DEFAULT_PYTHON = 3.8
HOME = /home/runner
command_line: /home/runner/work/astroid/astroid/venv/bin/coverage debug sys
sqlite3_version: 2.6.0
sqlite3_sqlite_version: 3.31.1
sqlite3_temp_store: 0
sqlite3_compile_options: COMPILER=gcc-9.4.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_PREUPDATE_HOOK; ENABLE_RTREE
ENABLE_SESSION; ENABLE_STMTVTAB; ENABLE_UNLOCK_NOTIFY
ENABLE_UPDATE_DELETE_LIMIT; HAVE_ISNAN; LIKE_DOESNT_MATCH_BLOBS
MAX_SCHEMA_RETRY=25; MAX_VARIABLE_NUMBER=250000; OMIT_LOOKASIDE
SECURE_DELETE; SOUNDEX; TEMP_STORE=1
THREADSAFE=1; USE_URI
> Debug log (new) - with 6.3.3
-- sys -------------------------------------------------------
coverage_version: 6.3.3
coverage_module: /home/runner/work/astroid/astroid/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
configs_read: /home/runner/work/astroid/astroid/.coveragerc
config_file: /home/runner/work/astroid/astroid/.coveragerc
config_contents: b'[paths]\nsource =\n astroid\n\n[report]\ninclude =\n astroid/*\nomit =\n */tests/*\nexclude_lines =\n # Re-enable default pragma\n pragma: no cover\n\n # Debug-only code\n def __repr__\n\n # Type checking code not executed during pytest runs\n if TYPE_CHECKING:\n @overload\n'
data_file: -none-
python: 3.11.0b1 (main, May 8 2022, 15:20:32) [GCC 9.4.0]
platform: Linux-5.13.0-1022-azure-x86_64-with-glibc2.31
implementation: CPython
executable: /home/runner/work/astroid/astroid/venv/bin/python
def_encoding: utf-8
fs_encoding: utf-8
pid: 1737
cwd: /home/runner/work/astroid/astroid
path: /home/runner/work/astroid/astroid/venv/bin
/opt/hostedtoolcache/Python/3.11.0-beta.1/x64/lib/python311.zip
/opt/hostedtoolcache/Python/3.11.0-beta.1/x64/lib/python3.11
/opt/hostedtoolcache/Python/3.11.0-beta.1/x64/lib/python3.11/lib-dynload
/home/runner/work/astroid/astroid/venv/lib/python3.11/site-packages
/home/runner/work/astroid/astroid
environment: DEFAULT_PYTHON = 3.8
HOME = /home/runner
command_line: /home/runner/work/astroid/astroid/venv/bin/coverage debug sys
sqlite3_version: 2.6.0
sqlite3_sqlite_version: 3.31.1
sqlite3_temp_store: 0
sqlite3_compile_options: COMPILER=gcc-9.4.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_PREUPDATE_HOOK; ENABLE_RTREE
ENABLE_SESSION; ENABLE_STMTVTAB; ENABLE_UNLOCK_NOTIFY
ENABLE_UPDATE_DELETE_LIMIT; HAVE_ISNAN; LIKE_DOESNT_MATCH_BLOBS
MAX_SCHEMA_RETRY=25; MAX_VARIABLE_NUMBER=250000; OMIT_LOOKASIDE
SECURE_DELETE; SOUNDEX; TEMP_STORE=1
THREADSAFE=1; USE_URI
============================= test session starts ==============================
@markshannon @pablogsal I am also seeing a problem with coverage.py being 2x slower on 3.11 than on 3.10:
Median for bug1339.py, python3.10, cov=none: 0.180s
Median for bug1339.py, python3.10, cov=6.4.1: 0.421s
Median for bug1339.py, python3.11, cov=none: 0.141s
Median for bug1339.py, python3.11, cov=6.4.1: 0.835s
Median for bm_sudoku.py, python3.10, cov=none: 10.946s
Median for bm_sudoku.py, python3.10, cov=6.4.1: 28.293s
Median for bm_sudoku.py, python3.11, cov=none: 10.215s
Median for bm_sudoku.py, python3.11, cov=6.4.1: 60.590s
Median for bm_spectral_norm.py, python3.10, cov=none: 14.882s
Median for bm_spectral_norm.py, python3.10, cov=6.4.1: 37.359s
Median for bm_spectral_norm.py, python3.11, cov=none: 10.415s
Median for bm_spectral_norm.py, python3.11, cov=6.4.1: 76.129s
Can you provide a reproducer that we can play with, as possible with the minimum set of dependencies possible?
Here are the same numbers in a more comprehensible form:
| Coverage | file | 3.10 | 3.11 | 3.11 vs 3.10 |
|---|---|---|---|---|
| none | bug1339.py | 0.180 s | 0.141 s | 78% |
| none | bm_sudoku.py | 10.946 s | 10.215 s | 93% |
| none | bm_spectral_norm.py | 14.882 s | 10.415 s | 70% |
| 6.4.1 | bug1339.py | 0.421 s | 0.835 s | 198% |
| 6.4.1 | bm_sudoku.py | 28.293 s | 60.590 s | 214% |
| 6.4.1 | bm_spectral_norm.py | 37.359 s | 76.129 s | 204% |
Here is how I ran the tests. You can adjust the details if you want.
- Get lab/benchmark.py from this repo: https://github.com/nedbat/coveragepy/blob/50e8d938315dacce9c5d3de1a25c771cdfe943ec/lab/benchmark.py
- Clone https://github.com/plasma-umass/slipcover . I put it at /src/slipcover
- Edit lines 250 and 251 to indicate where you cloned slipcover.
- Comment out line 365 to skip bug1339.py
- Run benchmark.py
It should do a good job making virtualenvs, installing coverage, and so on all by itself, though I'll be interested if you run into problems. If you want to change the parameters of the run, edit lines 348-369.
@nedbat Can you also open an issue ok CPython and subscribe me so we can track this "officially"? Thanks in advance!
@pablogsal I'm not sure how to subscribe you, but I pinged you, maybe that's what you meant: https://github.com/python/cpython/issues/93516
I opened https://github.com/nedbat/coveragepy/pull/1394, which I think should help at least a little.
Another idea, probably not particular to 3.11: Would it make sense to cache the latest result of PyDict_GetItem(self->should_trace_cache, filename)? I would guess, but I have no good data, that successive tracing calls would often have the the same filename, so a dictionary lookup could be avoided.
Would it make sense to cache the latest result of PyDict_GetItem(self->should_trace_cache, filename)?
That call only happens during a CALL event, so I'm not sure it would pay off, but I can try it.
I tried this out in this pull request: https://github.com/nedbat/coveragepy/pull/1401 It seemed to only improve things by about .5%