Code runs 77x times slower when using Decimal running with coverage.py on PyPy 3.9 (7.3.8)

[felipou]

Describe the bug
Running with coveragepy on PyPy drastically slows down programs using Decimal:

~/tmp/pypyperftest$ time poetry run coverage run -m covperftest.covperftest 10000000
10000000

real	7m37,942s
user	7m36,118s
sys	0m1,348s
~/tmp/pypyperftest$ time poetry run python -m covperftest.covperftest 10000000
10000000

real	0m5,891s
user	0m5,267s
sys	0m0,606s

I've noticed this issue while experimenting with PyPy's newest versions in the past, trying to migrate to Python 3.8. At the time I didn't pay much attention, just gave up. Now that PyPy launched a new version supporting 3.9, I tried to investigate a bit more and got the results above. At first I thought that maybe it was because PyPy is using Decimal with a pure Python implementation, but forcing the C implementation yields similar results (if not slower).

To Reproduce

1. What version of Python are you using?
   • Pypy 3.9 (7.3.8) - but I've noticed this problem while using earlier versions of PyPy.
2. What version of coverage.py shows the problem?
   • I tested with the latest release, version 6.3.2.
3. What versions of what packages do you have installed?
   • I tried to test in a virtualenv with as few packages as possible:

cffi==1.15.0
coverage==6.3.2
covperftest==1.0.0
greenlet==0.4.13
hpy==0.0.3
readline==6.2.4.1
tomli==2.0.1

1. What code shows the problem?
   • I'm not sure where the problem in coveragepy is (or if there's even a problem at all, maybe it's something related to how Decimal works on PyPy, but I thought it would be better to report this here).
2. What commands did you run?
   • I created a sample script to test this, which I executed in a virtualenv managed using poetry:

import random
import sys
from decimal import Decimal

size = int(sys.argv[1]) if len(sys.argv) > 1 else 100000

values = []
for _ in range(size):
    values.append(Decimal(3) * random.randint(0, 10000))
print(len(values), file=sys.stderr)

Expected behavior
Although a worse performance is to be expected when getting the coverage, it gets much worse when using Decimal. I tried the same code using just an integer, and the execution time was around 4.5x slower when using coveragepy. But when using Decimal, it was 77x slower.

[nedbat]

Hmm, I'm not sure what coverage.py could be doing that would affect Decimal specifically. @cfbolz, any ideas where to look?

[cfbolz]

hm, could it be that pypy is using the pure python implementation of decimal, and the code in there is tracked by coverage? whereas cpython uses a C extension, that receives no coverage information?

[nedbat]

I can definitely reproduce the results. The exact slowdown factor varies widely, but 50-80x is the range. The code is using the Python implementation of decimal, but coverage claims to not be tracing it:

% COVERAGE_DEBUG=trace python -m coverage run perftest.py 1000000
sys.path:
    /System/Volumes/Data/root/src/bugs/bug1339
    /usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9
    /usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/plat-mac
    /usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/plat-mac/lib-scriptpackages
    /usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages
Python stdlib matching: <TreeMatcher pylib ['/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9']>
Coverage code matching: <TreeMatcher coverage ['/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage']>
Third-party lib matching: <TreeMatcher third ['/Users/nedbatchelder/.local/bin', '/Users/nedbatchelder/.local/lib/pypy3.9/site-packages', '/usr/local/virtualenvs/tmp-c747330258bcd86/bin', '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy', '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages']>
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/threading.py': is in the stdlib
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage/execfile.py': is part of coverage.py
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/genericpath.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/stat.py': is in the stdlib
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage/files.py': is part of coverage.py
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage/python.py': is part of coverage.py
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/posixpath.py': is in the stdlib
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage/phystokens.py': is part of coverage.py
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/tokenize.py': is in the stdlib
Tracing 'perftest.py' as '/System/Volumes/Data/root/src/bugs/bug1339/perftest.py'
Not tracing '<frozen importlib._bootstrap>': not a real original file name
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/_distutils_hack/__init__.py': is a third-party module
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/_virtualenv.py': is a third-party module
Not tracing '<builtin>/frozen importlib._bootstrap_external': not a real original file name
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/decimal.py': is in the stdlib
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/pkg_resources/extern/__init__.py': is a third-party module
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/setuptools/extern/__init__.py': is a third-party module
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/setuptools/_vendor/importlib_metadata/_compat.py': is a third-party module
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/_pydecimal.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/collections/__init__.py': is in the stdlib
Not tracing '<string>': not a real original file name
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/contextvars.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/_contextvars.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/_immutables_map.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/reprlib.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/abc.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/_collections_abc.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/enum.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/re.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/types.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/sre_compile.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/sre_parse.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/random.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/subprocess.py': is in the stdlib
Not tracing '/usr/local/pypy/pypy3.9-v7.3.8-osx64/lib/pypy3.9/encodings/utf_8.py': is in the stdlib
1000000
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage/control.py': is part of coverage.py
Not tracing '/usr/local/virtualenvs/tmp-c747330258bcd86/lib/pypy3.9/site-packages/coverage/collector.py': is part of coverage.py

I don't know if having trace function in place causes a slow-down even if it's not tracing a frame?

[cfbolz]

Thanks @nedbat for confirming, I'll try to take a deeper look into what is going on here

[cfbolz]

(and thanks for showing me COVERAGE_DEBUG :-) )

[cfbolz]

Some information that I found out. The problem is definitely the fact that PyPy implements in Python all of decimal and even all of contextvars (which decimal uses a bit everywhere). One can see the same effect in CPython too by replacing the import with from _pydecimal import Decimal. On my laptop, that yields a roughly 10x slowdown.

On PyPy this is even more extreme. I added a simple trace hook that simply counts how many trace hook calls there are. Here are some numbers (details not super important, I was just trying to get a feel for the factors involved):

Implementation	Number of events (normalized to CPython)	Time coverage run (normalized to CPython)
CPython 3.10	1.0	1.0
CPython 3.10 python decimal	5.35	10.81
PyPy 3.9 (python decimal and contextvars)	7.07	29.66
PyPy 2 (python decimal, but no contextvars)	4.09	21.41

Ned's argument that a Python decimal (and contextvars) aren't traced is correct. However, the coverage trace function is still active for functions in those modules. This is needed because coverage needs to detect when we call something from the stdlib that is in the to-be-traced modules. The code paths that check whether we should collect data or not aren't free. Here's the relevant code path in the Python trace implementation for line events where we should ignore the function:

    def _trace(self, frame, event, arg_unused):
        if THIS_FILE in frame.f_code.co_filename:
            ...
        if (self.stopped and ...):
            ...
        if event == 'call':
            ...
        elif event == 'line':
            # Record an executed line.
            if self.cur_file_data is not None:
                ...
        return self._trace

This happens for every line event and is quite a bit of overhead (I've taken the code from coverage 6.3.2 as per the version number written above).

So, options? There are some things that we can fix on the PyPy side:

• I found a few small problems in PyPy that could improve things by a few percent, I will try to report back on those soon.
• PyPy could port contextvars to RPython (might be a good idea) but for decimal that looks really unlikely.
• PyPy could decide to mark some of the contextvar and or decimal implementation functions as "in Python but internal". Then they would not be traced, the debugger wouldn't see them and they wouldn't appear in tracebacks. It's an approach, but feels a bit unsatisfying to me.

Ideas on the Coverage end:

• I quickly hacked in [postponed] Set f_trace_lines = 0/False on ignored frames #791 (which sets frame.f_trace_line = False for code objects that aren't of interest) in my PyPy version, which improved the PyPy numbers by 2.7x (that's quite nice of course! but we need a lot more).
• another small win was the following experiment: the return self._trace at the end of the _trace method is making a new bound method object for every single trace event. Caching the bound method on self in the __init__ gave me an additional ~25% improvement on PyPy.
• The trace function itself could maybe be optimized in some other ways? It's a difficult balance I suspect.

That's it so far.

[cfbolz]

ok, so my pypy fixes are more useful than I thought, they also give a 50% performance improvement. on my laptop this brings the difference down to a much more acceptable 5x.

@nedbat do you think the two concrete coverage changes (a revived #791 and caching the bound method) make sense? I'm happy to prepare PRs for them.

[nedbat]

@cfbolz sure, those both sound good. I had forgotten about #791; it seems like the concerns with it are gone now that time has passed. Thanks!

[cfbolz]

ok, I'll give that a go! is there a "canonical" benchmark for coverage so that I can check whether it helps (or at least not worsens) other cases?

[cfbolz]

never mind, I should have just looked, sorry about that :-(

[nedbat]

TBH, I don't have a usual performance test. There's a perf directory, but I haven't used it in a very long time (years). It would be good to get a disciplined measurement established.

[cfbolz]

Thanks for the merge @nedbat :-). And thanks for putting the benchmark script together, I'll use that next time. I probably have one more PR coming.

[cfbolz]

@felipou would you be up to trying with a nightly build of pypy3.9 and a coverage master to see what the numbers now are for you?

[nedbat]

I tried a benchmark of the code from the top of this issue, and got:

Median for bug1339.py, pypy3.9, cov=none: 0.255s
Median for bug1339.py, pypy3.9, cov=6.4: 5.982s
Median for bug1339.py, pypy3.9, cov=tip: 2.420s

So latest coverage is 2x better than 6.4, though the slowdown I'm seeing is not nearly as severe as the OP's.

[cfbolz]

right, I was kind of assuming that the small benchmark was part of a bigger program

[felipou]

@cfbolz I'll give it a try as soon as I can, probably tomorrow night or wednesday morning.

[felipou]

Just ran some tests, got the following results using pypy 3.9 nightly and coverage from master branch:
Running without coverage - 0m5,712s
Running with coverage - 1m46,183s

So there was already a 4x speed-up compared to what I was getting before! 🚀

[nedbat]

There may be room for more improvements in the future, but I'll close this issue for now with a 4x speed up.

[nedbat]

This is now released as part of coverage 6.4.1.