Pytest 7.0 increases runtime significantly in Github Actions on Linux

[DanielNoord]

Bug
I don't have much information as of yet so sorry for the bare report, but I thought others might be running into similar issues and I couldn't find an opened issue yet.
We got a dependabot PR on pylint to update to 7.0: pylint-dev/pylint#5778.
However, the tests keep getting canceled after they hit our 30 minutes cut-off point. This only happens on Linux with Python 3.8, 3.9 and 3.10. In the first try 3.10 did manage to pass in about 3 minutes, but on try 2 and 3 it is also taking more than 30 minutes. The PR doesn't really change anything other than the version number and test are passing on main for these environments.
Other environments take between 3-6 minutes to run the full test suite, so taking longer than 30 minutes seems to be a real regression.

I can't reproduce this locally (yet) on my Mac.

TDLR: pytest 7.0 makes a test suite that normally takes about 5 minutes take more than 30 minutes on Linux with Python 3.8, 3.9 and 3.10. This is not consistent, as 3.10 has passed once.

Let me know if I can provide any other information!

Pip list
Locally I have used the following pip list and test pass in the expected time.
Note this is on Mac OS 12.1.

alabaster                         0.7.12
appdirs                           1.4.4
appnope                           0.1.2
asgiref                           3.4.1
astor                             0.8.1
astroid                           2.10.0.dev0 /Users/daniel/DocumentenLaptop/Programming/Github/astroid
attrs                             21.2.0
Babel                             2.9.1
backcall                          0.2.0
backports.entry-points-selectable 1.1.0
black                             21.12b0
bottle                            0.12.19
bytecode                          0.12.0
CD                                1.1.0
certifi                           2021.5.30
cfgv                              3.3.0
charset-normalizer                2.0.4
cli-ui                            0.10.3
click                             8.0.1
colorama                          0.4.4
contextlib2                       21.6.0
coverage                          6.2
coveralls                         3.3.1
debugpy                           1.4.1
decorator                         5.0.9
deepdiff                          5.5.0
dill                              0.3.4
distlib                           0.3.2
Django                            3.2.7
dnspython                         2.1.0
docopt                            0.6.2
docutils                          0.17.1
entrypoints                       0.3
execnet                           1.9.0
fett                              0.3.2
filelock                          3.0.12
flake8                            4.0.1
flake8-typing-imports             1.12.0
flynt                             0.66
gitdb                             4.0.9
GitPython                         3.1.24
gprof2dot                         2021.2.21
graphviz                          0.17
identify                          2.2.11
idna                              3.2
imagesize                         1.3.0
iniconfig                         1.1.1
ipykernel                         6.3.1
ipython                           7.27.0
ipython-genutils                  0.2.0
isort                             5.10.1
jedi                              0.18.0
Jinja2                            3.0.3
jupyter-client                    7.0.2
jupyter-core                      4.7.1
lazy-object-proxy                 1.6.0
libcst                            0.3.20
MarkupSafe                        2.0.1
matplotlib-inline                 0.1.2
mccabe                            0.6.1
MonkeyType                        21.5.0
mypy                              0.931
mypy-extensions                   0.4.3
nest-asyncio                      1.5.1
networkx                          2.6.3
nodeenv                           1.6.0
numpy                             1.21.1
ordered-set                       4.0.2
packaging                         21.0
parso                             0.8.2
pathspec                          0.9.0
pexpect                           4.8.0
pickleshare                       0.7.5
Pillow                            9.0.0
pip                               21.2.3
platformdirs                      2.2.0
pluggy                            0.13.1
pre-commit                        2.16.0
prompt-toolkit                    3.0.20
ptyprocess                        0.7.0
py                                1.10.0
py-cpuinfo                        8.0.0
pyannotate                        1.2.0
pycodestyle                       2.8.0
pydocstringformatter              0.3.0+dev   /Users/daniel/DocumentenLaptop/Programming/Github/DanielNoord/docstringformatter
pyenchant                         3.2.2
pyflakes                          2.4.0
Pygments                          2.10.0
pylint                            2.13.0.dev0 /Users/daniel/DocumentenLaptop/Programming/Github/pylint
pymongo                           3.12.1
pyparsing                         2.4.7
pyprof2calltree                   1.4.5
pytest                            7.0.0
pytest-benchmark                  3.4.1
pytest-cov                        3.0.0
pytest-forked                     1.3.0
pytest-profiling                  1.7.0
pytest-xdist                      2.5.0
python-dateutil                   2.8.2
python-docs-theme                 2021.11.1
python-jsonrpc-server             0.3.4
pytz                              2021.3
pyupgrade                         2.23.3
PyYAML                            5.4.1
pyzmq                             22.2.1
regex                             2021.7.6
requests                          2.26.0
rstcheck                          3.3.1
schema                            0.7.4
setuptools                        60.5.0
six                               1.16.0
smmap                             5.0.0
snakeviz                          2.1.0
snooty-lextudio                   1.11.6
snowballstemmer                   2.2.0
Sphinx                            4.3.0
sphinxcontrib-applehelp           1.0.2
sphinxcontrib-devhelp             1.0.2
sphinxcontrib-htmlhelp            2.0.0
sphinxcontrib-jsmath              1.0.1
sphinxcontrib-qthelp              1.0.3
sphinxcontrib-serializinghtml     1.1.5
sqlparse                          0.4.2
tabulate                          0.8.9
tbump                             6.6.1
tokenize-rt                       4.1.0
toml                              0.10.2
tomli                             1.2.0
tomlkit                           0.7.2
tornado                           6.1
tox                               3.24.1
traitlets                         5.1.0
types-pkg-resources               0.1.3
types-toml                        0.10.1
typing-extensions                 3.10.0.0
typing-inspect                    0.7.1
ujson                             1.35
Unidecode                         1.2.0
urllib3                           1.26.6
virtualenv                        20.7.0
watchdog                          1.0.2
wcwidth                           0.2.5
wrapt                             1.12.1

[nicoddemus]

@DanielNoord that's certainly weird.

I can't reproduce myself as I'm on Windows, but can you change the repos code to execute with -vv and --trace-config? --debug would also me helpful, however it currently writes a pytestdebug.log local file only.

Not sure if others have other ideas on how to debug this. 😕

[DanielNoord]

I ran the test suite with the mentioned arguments here: DanielNoord/pylint#83
I have "catted" the debug log so you should have access to it as well.

Obviously this time Linux Python 3.9 does pass in less than 5 minutes 😓

3.8 and 3.10 seem to be taking longer so let's hope they fail 😄

Let me know if you need anything else. I'm not sure about Github permissions but if you need contributor access to download the run logs just let me know and I can add anyone who wants/needs access.

Edit:
@nicoddemus All Windows jobs now also seems to fail with an interesting problem: https://github.com/DanielNoord/pylint/runs/5124333804?check_suite_focus=true.

Is this a known issue? I can make a new issue for this although I have no idea atm what is triggering this crash. Probably a combination of one of the arguments and some test file name that is not supported on Windows? Probably \u0142.

[bluetech]

I tried it by cloning pylint, installing requirements_test.txt and running with pytest 6.2.5 and pytest 7.0.0, with -n auto and without. I don't see a slowdown. This is Python 3.10 on Linux.

You can additionally try running with --durations=20 on CI. The top 5 slow tests for me are

35.11s call    tests/benchmark/test_baseline_benchmarks.py::TestEstablishBaselineBenchmarks::test_baseline_benchmark_j1_single_working_checker
5.71s call     tests/benchmark/test_baseline_benchmarks.py::TestEstablishBaselineBenchmarks::test_baseline_benchmark_j1_all_checks_lots_of_files
4.65s call     tests/test_pylint_runners.py::test_runner_with_arguments[run_epylint]
4.13s call     tests/benchmark/test_baseline_benchmarks.py::TestEstablishBaselineBenchmarks::test_baseline_benchmark_j10_single_working_checker
3.86s call     tests/test_pylint_runners.py::test_runner[run_epylint]

[nicoddemus]

I ran the test suite with the mentioned arguments here

Interesting, thanks.

tests/test_check_parallel.py::TestCheckParallelFramework::test_worker_initialize PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallelFramework::test_worker_initialize_pickling PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallelFramework::test_worker_check_single_file_uninitialised PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallelFramework::test_worker_check_single_file_no_checkers PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallelFramework::test_worker_check_sequential_checker PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_sequential_checkers_work PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_invoke_single_job PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[1-2-1] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[1-2-2] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[1-2-3] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[2-2-1] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[2-2-2] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[2-2-3] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-2-1] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-2-2] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-2-3] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-1-1] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-1-2] PASSED [  0%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-1-3] PASSED [  1%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-5-1] PASSED [  1%]
tests/test_check_parallel.py::TestCheckParallel::test_compare_workers_to_single_proc[3-5-2] PASSED [  1%]
Error: The operation was canceled.

Seems like it is getting stuck in test_compare_workers_to_single_proc. Can you comment out/skip the test temporarily to see if that test is indeed the culprit?

[DanielNoord]

I'll do a run with the test commented out. By the way, I think this might not be due to 7.0. I just noticed that on my own fork even main (which is on 6.2 is having similar issues. See: DanielNoord/pylint@851b63e and associated run.

Perhaps something changed in the Linux runner? I expected it was 7.0 as that was the first PR in which I saw this, but there might be another issue here...

I'll get back to you when I know how the run proceeded.

Edit: 3.8 and 3.10 seem to be failing again, even with the commented out test. 3.9 passed without any issues.

[DanielNoord]

After commenting out another test (test_map_reduce) the tests do run on all environments being tested on. (The tests that are failing on the latest commit are unrelated).

Some additional info:
For test_compare_workers_to_single_proc: 3.8 completes the (2, 10, 2) case and then gets stuck. 3.10 completes the
(3, 5, 2) case, but then gets stuck.

For test_map_reduce : 3.8 completes (10, 2, 3) and gets stuck. 3.10 completes (2, 10, 1) and then gets stuck.

The relevant tests are as follows:

    @pytest.mark.parametrize(
        "num_files,num_jobs,num_checkers",
        [
            (1, 2, 1),
            (1, 2, 2),
            (1, 2, 3),
            (2, 2, 1),
            (2, 2, 2),
            (2, 2, 3),
            (3, 2, 1),
            (3, 2, 2),
            (3, 2, 3),
            (3, 1, 1),
            (3, 1, 2),
            (3, 1, 3),
            (3, 5, 1),
            (3, 5, 2),
            (3, 5, 3),
            (10, 2, 1),
            (10, 2, 2),
            (10, 2, 3),
            (2, 10, 1),
            (2, 10, 2),
            (2, 10, 3),
        ],
    )
    def test_compare_workers_to_single_proc(self, num_files, num_jobs, num_checkers):
        """Compares the 3 key parameters for check_parallel() produces the same results

        The intent here is to ensure that the check_parallel() operates on each file,
        without ordering issues, irrespective of the number of workers used and the
        number of checkers applied.

        This test becomes more important if we want to change how we parametrise the
        checkers, for example if we aim to batch the files across jobs.
        """

        # define the stats we expect to get back from the runs, these should only vary
        # with the number of files.
        expected_stats = LinterStats(
            by_module={
                # pylint: disable-next=consider-using-f-string
                "--test-file_data-name-%d--"
                % idx: ModuleStats(
                    convention=0,
                    error=0,
                    fatal=0,
                    info=0,
                    refactor=0,
                    statement=18,
                    warning=0,
                )
                for idx in range(num_files)
            }
        )
        expected_stats.by_msg = {}
        expected_stats.convention = 0
        expected_stats.error = 0
        expected_stats.fatal = 0
        expected_stats.info = 0
        expected_stats.refactor = 0
        expected_stats.statement = 18 * num_files
        expected_stats.warning = 0

        file_infos = _gen_file_datas(num_files)

        # Loop for single-proc and mult-proc, so we can ensure the same linter-config
        for do_single_proc in range(2):
            linter = PyLinter(reporter=Reporter())

            # Assign between 1 and 3 checkers to the linter, they should not change the
            # results of the lint
            linter.register_checker(SequentialTestChecker(linter))
            if num_checkers > 1:
                linter.register_checker(ExtraSequentialTestChecker(linter))
            if num_checkers > 2:
                linter.register_checker(ThirdSequentialTestChecker(linter))

            if do_single_proc:
                # establish the baseline
                assert (
                    linter.config.jobs == 1
                ), "jobs>1 are ignored when calling _check_files"
                linter._check_files(linter.get_ast, file_infos)
                assert linter.msg_status == 0, "We should not fail the lint"
                stats_single_proc = linter.stats
            else:
                check_parallel(
                    linter,
                    jobs=num_jobs,
                    files=file_infos,
                    arguments=None,
                )
                stats_check_parallel = linter.stats
                assert linter.msg_status == 0, "We should not fail the lint"

        assert str(stats_single_proc) == str(
            stats_check_parallel
        ), "Single-proc and check_parallel() should return the same thing"
        assert str(stats_check_parallel) == str(
            expected_stats
        ), "The lint is returning unexpected results, has something changed?"

    @pytest.mark.parametrize(
        "num_files,num_jobs,num_checkers",
        [
            (2, 2, 1),
            (2, 2, 2),
            (2, 2, 3),
            (3, 2, 1),
            (3, 2, 2),
            (3, 2, 3),
            (3, 1, 1),
            (3, 1, 2),
            (3, 1, 3),
            (3, 5, 1),
            (3, 5, 2),
            (3, 5, 3),
            (10, 2, 1),
            (10, 2, 2),
            (10, 2, 3),
            (2, 10, 1),
            (2, 10, 2),
            (2, 10, 3),
        ],
    )
    def test_map_reduce(self, num_files, num_jobs, num_checkers):
        """Compares the 3 key parameters for check_parallel() produces the same results

        The intent here is to validate the reduce step: no stats should be lost.

        Checks regression of https://github.com/PyCQA/pylint/issues/4118
        """

        # define the stats we expect to get back from the runs, these should only vary
        # with the number of files.
        file_infos = _gen_file_datas(num_files)

        # Loop for single-proc and mult-proc, so we can ensure the same linter-config
        for do_single_proc in range(2):
            linter = PyLinter(reporter=Reporter())

            # Assign between 1 and 3 checkers to the linter, they should not change the
            # results of the lint
            linter.register_checker(ParallelTestChecker(linter))
            if num_checkers > 1:
                linter.register_checker(ExtraParallelTestChecker(linter))
            if num_checkers > 2:
                linter.register_checker(ThirdParallelTestChecker(linter))

            if do_single_proc:
                # establish the baseline
                assert (
                    linter.config.jobs == 1
                ), "jobs>1 are ignored when calling _check_files"
                linter._check_files(linter.get_ast, file_infos)
                stats_single_proc = linter.stats
            else:
                check_parallel(
                    linter,
                    jobs=num_jobs,
                    files=file_infos,
                    arguments=None,
                )
                stats_check_parallel = linter.stats
        assert str(stats_single_proc.by_msg) == str(
            stats_check_parallel.by_msg
        ), "Single-proc and check_parallel() should return the same thing"

[nicoddemus]

Thanks @DanielNoord,

Looking at the tests, nothing jumps to the eyes... however I notice that the tests themselves don't use pytest features, so one thing I would try is to move the tests to a normal Python file and invoke them normally (not using pytest), for example:

    @pytest.mark.parametrize(
        "num_files,num_jobs,num_checkers",
        [
            (1, 2, 1),
            (1, 2, 2),
            (1, 2, 3),
            (2, 2, 1),
            (2, 2, 2),
            (2, 2, 3),
            (3, 2, 1),
            (3, 2, 2),
            (3, 2, 3),
            (3, 1, 1),
            (3, 1, 2),
            (3, 1, 3),
            (3, 5, 1),
            (3, 5, 2),
            (3, 5, 3),
            (10, 2, 1),
            (10, 2, 2),
            (10, 2, 3),
            (2, 10, 1),
            (2, 10, 2),
            (2, 10, 3),
        ],
    )
    def test_compare_workers_to_single_proc(self, num_files, num_jobs, num_checkers):
        ...

Into:

    def test_compare_workers_to_single_proc(num_files, num_jobs, num_checkers):
        ...

    for num_files,num_jobs,num_checkers in [
            (1, 2, 1),
            (1, 2, 2),
            (1, 2, 3),
            (2, 2, 1),
            (2, 2, 2),
            (2, 2, 3),
            (3, 2, 1),
            (3, 2, 2),
            (3, 2, 3),
            (3, 1, 1),
            (3, 1, 2),
            (3, 1, 3),
            (3, 5, 1),
            (3, 5, 2),
            (3, 5, 3),
            (10, 2, 1),
            (10, 2, 2),
            (10, 2, 3),
            (2, 10, 1),
            (2, 10, 2),
            (2, 10, 3),
    ]:
        test_compare_workers_to_single_proc(num_files, num_jobs, num_checkers)        

And execute with python foo.py, and see if that locks up CI or not.

[DanielNoord]

I just did a test with test_compare_workers_to_single_proc. (I couldn't get the other to work due to some pickling issues, which seem unrelated).

See the run: https://github.com/DanielNoord/pylint/runs/5126516580?check_suite_focus=true. Related PR is still DanielNoord/pylint#83.
The cat log file step (should have changed the name) shows the result of running test_compare_workers_to_single_proc form a for loop. As you can see all calls exit and pass correctly..
I'd be happy to do the run again and try and get test_map_reduce to work as well, but from this first run it seems that there is at least some sort of relation to pytest.

[DanielNoord]

This turned out to be an issue with our tests. We aren't sure what caused this to suddenly regress, but it doesn't seem to be related to pytest.

Thanks for the help anyway! Closing 😄

[DanielNoord]

@nicoddemus Since you were so helpful previously I'm going to ask you for a little help again.
The issue reported here still hasn't been resolved and I'm not sure what else we can do so I'm wondering if you have any good ideas.

After multiple other potential fixes and changes we still believe the issue has something to do with multiprocessing, how we invoke it and perhaps something with how pytest deals with that. In pylint-dev/pylint#6066 I tried my latest idea: add a marker that skips these tests when we have less than one core available for the process.

As you can see I decorated test_compare_workers_to_single_proc with it, so we should only run the test when 2 or more cores are available. After some tries I got the CI to time our again on this PR in https://github.com/PyCQA/pylint/runs/5785215484?check_suite_focus=true. However, the decorated tests ran. So apparently we do have two cores (this is also mentioned by Github, but we theorised that these might not always be accessible by the current process when runners were shared or something like that..)

One thing I do notice is that there is no line 25 with the start of the next parametrised test. I would imagine that if we hang somewhere in our multiprocessing.Pool call then we would see the next test being started but then never getting a PASSED, SKIPPED or FAILED at the end of the line. Or is this always the case in Github Actions? That the PASSED line only shows up after the test has ran?

If not I wonder if there is something/process that hasn't been closed after the test which blocks pytest from going to the next parametrised test? We really have no idea what is going wrong here so I'm just trying to come up with stuff that I could imagine could be problematic.

Btw, is there a way to make --debug print out during the run? Perhaps that could help?

Edit: I used the environment variable and got two runs that ended up hanging:
Run 1:
https://github.com/DanielNoord/pylint/actions/runs/2076750863/attempts/1
https://pipelines.actions.githubusercontent.com/serviceHosts/33228b92-9bd8-4db1-82c5-ff29ed8165e2/_apis/pipelines/1/runs/613/signedlogcontent/54?urlExpires=2022-04-01T11%3A33%3A39.8753595Z&urlSigningMethod=HMACV1&urlSignature=VYLZeJUX8JGPbQ%2FjrxL9Yz%2BGk7WZU0L119DrPjJrCJ8%3D

Run 2:
https://github.com/DanielNoord/pylint/actions/runs/2076750861/attempts/7
https://pipelines.actions.githubusercontent.com/serviceHosts/33228b92-9bd8-4db1-82c5-ff29ed8165e2/_apis/pipelines/1/runs/626/signedlogcontent/56?urlExpires=2022-04-01T11%3A31%3A23.2521384Z&urlSigningMethod=HMACV1&urlSignature=MmEh3IswgLlJxXp3ngEx23XHKJZxFNUUxiVNuQ5lXyY%3D

Both hang on a test that involves the use of multiprocessing.Pool. I'm not sure what I'm looking at in those debug traces, but perhaps you see something out of order?