Performance of coverage.py under 3.11 #1287

markshannon · 2021-11-29T11:39:35Z

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

nedbat · 2021-11-29T14:36:58Z

Can you say more about why you are concerned? Has something slowed down? What is it you would like me to do?

pablogsal · 2021-11-29T15:20:55Z

Can you say more about why you are concerned? Has something slowed down? What is it you would like me to do?

Check python/cpython#29729 (comment) for instance

markshannon · 2021-12-06T15:49:08Z

What is it you would like me to do?

Nothing for now, but thanks for the offer.

cdce8p · 2022-05-14T12:53:19Z

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.

nedbat · 2022-05-14T13:40:25Z

@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 · 2022-05-14T16:22:15Z

@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?

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 ==============================

nedbat · 2022-06-03T17:41:25Z

@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

pablogsal · 2022-06-03T18:12:10Z

Can you provide a reproducer that we can play with, as possible with the minimum set of dependencies possible?

nedbat · 2022-06-03T18:29:03Z

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%

nedbat · 2022-06-03T18:35:34Z

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.

pablogsal · 2022-06-04T02:39:21Z

@nedbat Can you also open an issue ok CPython and subscribe me so we can track this "officially"? Thanks in advance!

nedbat · 2022-06-05T12:22:31Z

@pablogsal I'm not sure how to subscribe you, but I pinged you, maybe that's what you meant: python/cpython#93516

pablogsal · 2022-06-05T12:24:08Z

Thanks @nedbat 🙏 I marked the bug as release blocker

sweeneyde · 2022-06-06T04:58:28Z

I opened #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.

nedbat · 2022-06-11T10:14:08Z

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.

nedbat · 2022-06-11T20:19:25Z

I tried this out in this pull request: #1401 It seemed to only improve things by about .5%

markshannon added enhancement New feature or request needs triage labels Nov 29, 2021

markshannon mentioned this issue Nov 29, 2021

bpo-45786: Allocate space for frame in frame object. python/cpython#29729

Merged

nedbat removed the needs triage label Dec 6, 2021

cdce8p mentioned this issue May 14, 2022

Pin Python 3.11.0b1 [ci] pylint-dev/astroid#1560

Closed

nedbat added next performance Something is too slow and removed enhancement New feature or request labels Jun 3, 2022

pablogsal mentioned this issue Jun 4, 2022

gh-93382: Cache result of PyCode_GetCode in codeobject python/cpython#93383

Merged

nedbat mentioned this issue Jun 5, 2022

Severe performance degradation for tracing under 3.11 python/cpython#93516

Open

Fidget-Spinner mentioned this issue Jun 6, 2022

Use PyCode_GetCode #1394

Merged

pquentin mentioned this issue Jun 12, 2022

Python 3.11.0 alpha 7 times out in CI urllib3/urllib3#2602

Closed

detoyz mentioned this issue Jan 4, 2023

Perfromance drop in 7.0.2 comparing to 7.0.1 #1527

Closed

153957 mentioned this issue Nov 12, 2024

Expected performance of coveragepy? #1862

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Performance of coverage.py under 3.11 #1287

Performance of coverage.py under 3.11 #1287

markshannon commented Nov 29, 2021

nedbat commented Nov 29, 2021

pablogsal commented Nov 29, 2021

markshannon commented Dec 6, 2021 •

edited

Loading

cdce8p commented May 14, 2022 •

edited

Loading

nedbat commented May 14, 2022

cdce8p commented May 14, 2022 •

edited

Loading

nedbat commented Jun 3, 2022

pablogsal commented Jun 3, 2022

nedbat commented Jun 3, 2022 •

edited

Loading

nedbat commented Jun 3, 2022 •

edited

Loading

pablogsal commented Jun 4, 2022

nedbat commented Jun 5, 2022

pablogsal commented Jun 5, 2022

sweeneyde commented Jun 6, 2022

nedbat commented Jun 11, 2022

nedbat commented Jun 11, 2022

Performance of coverage.py under 3.11 #1287

Performance of coverage.py under 3.11 #1287

Comments

markshannon commented Nov 29, 2021

nedbat commented Nov 29, 2021

pablogsal commented Nov 29, 2021

markshannon commented Dec 6, 2021 • edited Loading

cdce8p commented May 14, 2022 • edited Loading

nedbat commented May 14, 2022

cdce8p commented May 14, 2022 • edited Loading

nedbat commented Jun 3, 2022

pablogsal commented Jun 3, 2022

nedbat commented Jun 3, 2022 • edited Loading

nedbat commented Jun 3, 2022 • edited Loading

pablogsal commented Jun 4, 2022

nedbat commented Jun 5, 2022

pablogsal commented Jun 5, 2022

sweeneyde commented Jun 6, 2022

nedbat commented Jun 11, 2022

nedbat commented Jun 11, 2022

markshannon commented Dec 6, 2021 •

edited

Loading

cdce8p commented May 14, 2022 •

edited

Loading

cdce8p commented May 14, 2022 •

edited

Loading

nedbat commented Jun 3, 2022 •

edited

Loading

nedbat commented Jun 3, 2022 •

edited

Loading