Tests take longer to run when coverage context is recorded, expected?

[fersarr]

Perhaps you are already aware of this and it is expected, but at least for the purpose of documenting it:

Running tests while recording coverage context for who-tests-what (by using the .coveragerc mentioned below), takes considerably longer than usual. As a small example, running 300 unit tests used to take 15 seconds and with this it takes around 50 seconds. On bigger batches of tests it became quite impactful. Perhaps this is all expected.

The .coveragerc file is:

[run]
dynamic_context = test_function

As described in https://nedbatchelder.com/blog/201810/who_tests_what_is_here.html

The command was:

python coverage run -p --branch /path/py.test tests/unit/module/

Measured on:

Python==3.6.5
coverage==5.0a4

[fersarr]

The combine stage also takes considerably longer. It's really hard to provide reproducible examples for this kind of things, but to give you an idea:

In a particular repo of ours:

a) The coverage step would take less than 5 minutes with coverage v4.
b) With coverage v5 it takes around 12 minutes
c) With coverage v5 plus dynamic_context=test_function it takes 2.5 hours for each file!

Here is a timeline of running combine with --debug dataio:

11:43:31 coverage combine --debug dataio
11:43:31 Combining data file 'path/.coverage.zzz-6.hostxxx.2493.308503'
11:43:31 Opening data file 'path/.coverage.zzz-6.hostxxx.2493.308503'
11:43:31 Erasing data file 'path/.coverage'
11:43:31 Creating data file 'path/.coverage'
14:31:42 Deleting combined data file 'path/.coverage.zzz-6.hostxxx.2493.308503'
14:31:42 Combining data file 'path/.coverage.zzz-19.hostxxx.1543.696946'
14:31:42 Opening data file 'path/.coverage.zzz-19.hostxxx.1543.696946'
17:07:24 Deleting combined data file 'path/.coverage.zzz-19.hostxxx.1543.696946'
17:07:24 Combining data file 'path/.coverage.zzz-7.hostxxx.16274.212466'
17:07:24 Opening data file 'path/.coverage.zzz-7.hostxxx.16274.212466'

The .coverage.xxx files in that directory are ~15 and each of them is 1 to 7 Mb in size

Let me know if I can be more helpful by using other --debug options

[nedbat]

There are some speed fixes on master. Can you try that?

[fersarr]

Thanks Ned. I have tried the master branch and it seems that the speed for coverage combine has improved. From more than 10 hours to around 10-20 minutes!

The coverage run stage is still multiple times (2x to 5x) slower though. Even for a small number of unit tests (~200)

[nedbat]

I'd like to do some profiling to understand where the extra time is going...

[nedbat]

I've made some more speed improvements on master. Can you try them?

[fersarr]

Seems like there are some improvements :)

with 1000 tests (defined in the file test_file_1.py below)

coveragepy v4                       4.37 secs
coveragepy v5.0a5                   2 runs: 197 secs, 184 secs
coveragepy v5.0a6                   2 runs: 137 secs, 142 secs
coverage master (8466069620)        2 runs: 100 secs, 95 secs

using pytest==3.8.2

I created this small test to do this, so that you can reproduce it too:

$ ls -l
 .
test_file_1.py
sourcefile1.py
.coveragerc

where

test_file_1.py is

import pytest
import sourcefile1

tests = tuple(f'test{i}' for i in range(1000))

@pytest.mark.parametrize("input_str", tests)
def test_speed(input_str):
    print(input_str)
    number = sourcefile1.get_random_number()
    assert number <= 20
    assert number >= 5

sourcefile1.py is

import random

def get_random_number():
	return random.randint(5, 20)

.coveragerc is

[run]
dynamic_context = test_function

and I am running the test with:

python /path..../bin/coverage run -p --branch /path..../bin/pytest -svvv test_file_1.py

[nedbat]

Now I get these results. All are averages of four runs, using Python 3.6.9:

Without branch coverage:
time python -m coverage run -m pytest test_file1.py
- coverage.py 4.5.4:                         3.19s
- coverage.py 5.0a8 (without contexts)       3.19s
- coverage.py 5.0a8 (with contexts)          6.94s

With branch coverage:
time python -m coverage run --branch -m pytest test_file1.py
- coverage.py 4.5.4:                         4.04s
- coverage.py 5.0a8 (without contexts)       4.18s
- coverage.py 5.0a8 (with contexts)         11.45s

I think that performance is good enough for beta!

[nedbat]

I did some more measurements, using hyperfine to run 10 times each. This time, I've included pytest-cov measurements to see how it improves things.

No coverage
python -m pytest test_file1.py                                                           1.962 s

Coverage 4.5.4
python -m coverage run -m pytest test_file1.py                                           2.939 s
python -m coverage run --branch -m pytest test_file1.py                                  3.759 s
python -m pytest --cov=. --cov-report= test_file1.py                                     2.521 s
python -m pytest --cov=. --cov-report= --cov-branch test_file1.py                        2.581 s

Coverage 5.0a8, no contexts
python -m coverage run -m pytest test_file1.py                                           3.012 s
python -m coverage run --branch -m pytest test_file1.py                                  3.947 s
python -m pytest --cov=. --cov-report= test_file1.py                                     2.733 s
python -m pytest --cov=. --cov-report= --cov-branch test_file1.py                        2.611 s

Coverage 5.0a8, with test contexts
python -m coverage run -m pytest test_file1.py                                           6.481 s
python -m coverage run --branch -m pytest test_file1.py                                 10.581 s
python -m pytest --cov=. --cov-report= test_file1.py                                     4.215 s
python -m pytest --cov=. --cov-report= --cov-branch test_file1.py                        4.118 s

Coverage 5.0a8, with pytest-cov contexts
python -m pytest --cov=. --cov-report= --cov-context=test test_file1.py                  3.829 s
python -m pytest --cov=. --cov-report= --cov-branch --cov-context=test test_file1.py     3.868 s

[nedbat]

BTW, the script that ran those tests: https://github.com/nedbat/coveragepy/blob/master/lab/compare_times.sh