Possible performance regression with Coverage >=5

[tigarmo]

Describe the bug
Total coverage run time is considerable bigger in Coverage 5, as compared to 4.5.3

To Reproduce
How can we reproduce the problem? Please be specific. Don't just link to a failing CI job. Answer the questions below:

• What version of Python are you using?
  3.6.7

• What version of coverage.py are you using? The output of coverage debug sys is helpful.
  Both versions of Coverage are installed with pip.
  For Coverage 5.3:

-- sys -------------------------------------------------------
                        version: 5.3
                       coverage: w:\1\projects\coverage-test\lib\site-packages\coverage\__init__.py
                         tracer: -none-
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-
      plugins.context_switchers: -none-
              configs_attempted: .coveragerc
                                 setup.cfg
                                 tox.ini
                                 pyproject.toml
                   configs_read: -none-
                    config_file: None
                config_contents: -none-
                      data_file: -none-
                         python: 3.6.7 (default, Mar  4 2020, 17:08:00) [MSC v.1900 64 bit (AMD64)]
                       platform: Windows-10-10.0.19041-SP0
                 implementation: CPython
                     executable: w:\1\projects\coverage-test\scripts\python.exe
                   def_encoding: utf-8
                    fs_encoding: utf-8
                            pid: 17812
                            cwd: W:\1\Projects\coverage-test
                           path: W:\1\Projects\coverage-test\Scripts\coverage.exe
                                 w:\1\projects\coverage-test\scripts\python36.zip
                                 W:\Miniconda\DLLs
                                 W:\Miniconda\lib
                                 W:\Miniconda
                                 w:\1\projects\coverage-test
                                 w:\1\projects\coverage-test\lib\site-packages
                    environment: CONDA_PY = 36
                   command_line: W:\1\Projects\coverage-test\Scripts\coverage debug sys
                sqlite3_version: 2.6.0
         sqlite3_sqlite_version: 3.21.0
             sqlite3_temp_store: 0
        sqlite3_compile_options: COMPILER=msvc-1900
                                 ENABLE_FTS4
                                 ENABLE_FTS5
                                 THREADSAFE=1

For Coverage 4.5.3:

-- sys -------------------------------------------------------
              version: 4.5.3
             coverage: w:\1\projects\coverage-test\lib\site-packages\coverage\__init__.py
          cover_paths: W:\1\Projects\coverage-test\Lib\site-packages\coverage
          pylib_paths: W:\Miniconda\Lib
               tracer: CTracer
 plugins.file_tracers: -none-
  plugins.configurers: -none-
         config_files: .coveragerc
                       setup.cfg
                       tox.ini
         configs_read: -none-
            data_path: W:\1\Projects\coverage-test\.coverage
               python: 3.6.7 (default, Mar  4 2020, 17:08:00) [MSC v.1900 64 bit (AMD64)]
             platform: Windows-10-10.0.19041-SP0
       implementation: CPython
           executable: w:\1\projects\coverage-test\scripts\python.exe
                  cwd: W:\1\Projects\coverage-test
                 path:
                       w:\1\projects\coverage-test\scripts\python36.zip
                       W:\Miniconda\DLLs
                       W:\Miniconda\lib
                       W:\Miniconda
                       w:\1\projects\coverage-test
                       w:\1\projects\coverage-test\lib\site-packages
          environment: -none-
         command_line: W:\1\Projects\coverage-test\Scripts\coverage debug sys
         source_match: -none-
    source_pkgs_match: -none-
        include_match: -none-
           omit_match: -none-
          cover_match: W:\1\Projects\coverage-test\Lib\site-packages\coverage
          pylib_match: W:\Miniconda\Lib

• What versions of what packages do you have installed? The output of pip freeze is helpful.

Other than Coverage itself, these are the packages:

atomicwrites==1.4.0
attrs==20.2.0
colorama==0.4.3
coverage==5.3
importlib-metadata==2.0.0
iniconfig==1.0.1
packaging==20.4
pluggy==0.13.1
py==1.9.0
pyparsing==2.4.7
pytest==6.1.1
six==1.15.0
toml==0.10.1
zipp==3.3.0

• What code are you running? Give us a specific commit of a specific repo that we can check out.

I'm running a single pytest test module:

def test_dummy():
    assert True

• What commands did you run?

I wrote the following script to output the Coverage version, run coverage + pytest (without pytest-cov) on my single test module, then print the time the command took. The catch here is that I'm adding the pandas source codebase via --source, even though my test doesn't use pandas and indeed the package isn't even installed. I've currently found that this addition makes the command take way longer. I'm doing this for the purposes of this bug report, as an attempt to make the bug "easily" reproducible, but the problem was first identified when running coverage on a proprietary codebase.

Here's the script:

import subprocess
import time

subprocess.run(['coverage', '--version'])

command = r'coverage run --source=../pandas/pandas,src -m pytest src/test_dummy.py'
start = time.time()
subprocess.run(command.split(' '))
end = time.time()
print(f'Time: {end-start} s')

Here's the output with Coverage 4.5.3:

(coverage-test) λ python time_cov.py
Coverage.py, version 4.5.3 with C extension
Documentation at https://coverage.readthedocs.io
============================================================================================================ test session starts ============================================================================================================
platform win32 -- Python 3.6.7, pytest-6.1.1, py-1.9.0, pluggy-0.13.1
rootdir: W:\1\Projects\coverage-test
collected 1 item

src\test_dummy.py .                                                                                                                                                                                                                    [100%]

============================================================================================================= 1 passed in 0.01s =============================================================================================================
Time: 0.4677555561065674 s

Here's the output with Coverage 5.3:

(coverage-test) λ python time_cov.py
Coverage.py, version 5.3 with C extension
Full documentation is at https://coverage.readthedocs.io
============================================================================================================ test session starts ============================================================================================================
platform win32 -- Python 3.6.7, pytest-6.1.1, py-1.9.0, pluggy-0.13.1
rootdir: W:\1\Projects\coverage-test
collected 1 item

src\test_dummy.py .                                                                                                                                                                                                                    [100%]

============================================================================================================= 1 passed in 0.01s =============================================================================================================
Time: 5.179388761520386 s

Expected behavior
I expected Coverage 5.3 to take as much time as 4.5.3 (half a second), but the command took 5 seconds.

Additional context
None that I can think of right now! Please let me know if more info is needed

[nicoddemus]

The catch here is that I'm adding the pandas source codebase via --source, even though my test doesn't use pandas and indeed the package isn't even installed.

In the codebase, is also the case that some package is not installed, or this is just a way to reproduce the slow down?

[tigarmo]

In the codebase, is also the case that some package is not installed, or this is just a way to reproduce the slow down?

Thanks, this is just a way to reproduce the slowdown. I found that I had to point Coverage at a large enough codebase/source tree to get the problem that we're having with our own codebase to show up in a reproducible manner. If I use only --source=src I get no slowdown, which is expected because the Python code here is just that single test.

[tigarmo]

Something that might not be clear from the output is that in both versions the pytest run itself is very fast (0.01s), as expected from the simplicity of the test. The slowdown itself happens after pytest has written its test report.

[nedbat]

I see something like what you are seeing, but not as extreme. Using pandas as the burden, I get 0.604s for 4.5.3 and 1.369s for 5.3. I don't understand why it would be slower though, so I will look into it.

[nedbat]

I've fixed this in 3274cba. Can you try installing it to see if it works in your environment?

pip install git+https://github.com/nedbat/coveragepy.git@3274cbad045d9ee2e67384564d772a019cad0c9e#egg=coverage==0.0

[tigarmo]

Thanks for the quick fix! I confirm that this also solves the slowdown on my case.

[nedbat]

This is now released as part of coverage 5.3.1.

[tigarmo]

thanks!