Tests take longer to run when coverage context is recorded, expected?
fersarr opened this issue · 12 comments
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
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
There are some speed fixes on master. Can you try that?
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)
I'd like to do some profiling to understand where the extra time is going...
I've made some more speed improvements on master. Can you try them?
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
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!
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
BTW, the script that ran those tests: https://github.com/nedbat/coveragepy/blob/master/lab/compare_times.sh
Thanks for that detailed breakdown! 😄 Really insightful. Sorry I am not following, why are pytest-cov contexts expected to be faster and what are they?
pytest-cov is a pytest plugin for coordinating coverage measurement during test runs. It's faster for two reasons:
- It starts coverage after pytest has collected tests, etc, so those early phases of pytest are not subject to the usual coverage slow-down
- It uses internal pytest events to switch the dynamic context. Without that, coverage has to constantly check whether a new test has started.
Thank you!