with_plugins fixture duplicates test execution time.

[pdelboca]

CKAN version

master, 2.10

Describe the bug

Using with_plugins fixture kills test performance.

Steps to reproduce

1. Create a simple test:

def test_home_renders(app):
    app.get("/", status=200)

2. Execute the test and measure the performance (1.5 sec including loading time)
3. Add with_plugins fixture to it with some plugins installed in the environment. Example:

import pytest

@pytest.mark.usefixtures("with_plugins")
@pytest.mark.ckan_config("ckan.plugins", "showcase pages datastore")
def test_home_renders(app):
    app.get("/", status=200)

4. Execute the test and measure the performance (3.15sec including loading time)

When running more tests:

class TestFunctionalInteraction:
    def test_home_renders1(self, app):
        app.get("/", status=200)

    def test_home_renders2(self, app):
        app.get("/", status=200)

    def test_home_renders3(self, app):
        app.get("/", status=200)

    def test_home_renders4(self, app):
        app.get("/", status=200)

    def test_home_renders5(self, app):
        app.get("/", status=200)

    def test_home_renders6(self, app):
        app.get("/", status=200)

This runs in 6 passed in 5.25s

Adding with_plugins:

import pytest

@pytest.mark.usefixtures("with_plugins")
@pytest.mark.ckan_config("ckan.plugins", "showcase pages datastore")
class TestFunctionalInteraction:
    def test_home_renders1(self, app):
        app.get("/", status=200)

    def test_home_renders2(self, app):
        app.get("/", status=200)

    def test_home_renders3(self, app):
        app.get("/", status=200)

    def test_home_renders4(self, app):
        app.get("/", status=200)

    def test_home_renders5(self, app):
        app.get("/", status=200)

    def test_home_renders6(self, app):
        app.get("/", status=200)

6 passed in 13.67s

Expected behavior

A similar running time than 2.9?

Additional details

While doing some profiling the performance issue since to come from parsing the config declaration (load_core_declaration) each time we unload() every plugin.

Profiling without the fixture

Mon Dec 19 19:16:14 2022    /home/pdelboca/Repos/ckan/prof/combined.prof

         13493104 function calls (13140526 primitive calls) in 7.613 seconds

   Ordered by: cumulative time
   List reduced from 4199 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        6    0.000    0.000    7.626    1.271 runner.py:108(pytest_runtest_protocol)
        6    0.000    0.000    7.623    1.271 runner.py:116(runtestprotocol)
       18    0.000    0.000    7.623    0.424 runner.py:216(call_and_report)
   181/66    0.001    0.000    7.623    0.115 hooks.py:272(__call__)
   181/66    0.000    0.000    7.622    0.115 manager.py:90(_hookexec)
   181/66    0.000    0.000    7.622    0.115 manager.py:84(<lambda>)
   181/66    0.002    0.000    7.622    0.115 callers.py:157(_multicall)
       18    0.000    0.000    7.620    0.423 runner.py:244(call_runtest_hook)
       18    0.000    0.000    7.620    0.423 runner.py:315(from_call)
       18    0.000    0.000    7.619    0.423 runner.py:259(<lambda>)
       42    0.000    0.000    5.316    0.127 fixtures.py:553(getfixturevalue)
        6    0.000    0.000    5.316    0.886 runner.py:152(pytest_runtest_setup)
    97/42    0.000    0.000    5.316    0.127 fixtures.py:568(_get_active_fixturedef)
        6    0.000    0.000    5.316    0.886 runner.py:475(setup)
    36/18    0.000    0.000    5.315    0.295 fixtures.py:596(_compute_fixture_value)
        6    0.000    0.000    5.315    0.886 python.py:1763(setup)
        6    0.000    0.000    5.315    0.886 fixtures.py:546(_fillfixtures)
    36/18    0.000    0.000    5.315    0.295 fixtures.py:1039(execute)
       31    0.000    0.000    5.312    0.171 fixtures.py:1106(pytest_fixture_setup)
       31    0.000    0.000    5.312    0.171 fixtures.py:884(call_fixture_func)

Profiling with the fixture

Mon Dec 19 19:12:55 2022    /home/pdelboca/Repos/ckan/prof/combined.prof

         38429233 function calls (37904138 primitive calls) in 17.468 seconds

   Ordered by: cumulative time
   List reduced from 4825 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        6    0.000    0.000   17.487    2.914 runner.py:108(pytest_runtest_protocol)
        6    0.000    0.000   17.485    2.914 runner.py:116(runtestprotocol)
       18    0.000    0.000   17.485    0.971 runner.py:216(call_and_report)
   199/66    0.001    0.000   17.484    0.265 hooks.py:272(__call__)
   199/66    0.000    0.000   17.484    0.265 manager.py:90(_hookexec)
   199/66    0.000    0.000   17.484    0.265 manager.py:84(<lambda>)
   199/66    0.002    0.000   17.484    0.265 callers.py:157(_multicall)
       18    0.000    0.000   17.482    0.971 runner.py:244(call_runtest_hook)
       18    0.000    0.000   17.482    0.971 runner.py:315(from_call)
       18    0.000    0.000   17.481    0.971 runner.py:259(<lambda>)
       48    0.001    0.000   13.947    0.291 core.py:196(plugins_update)
       48    0.005    0.000   13.943    0.290 environment.py:107(update_config)
57220/23350    0.013    0.000   10.912    0.000 {built-in method builtins.next}
       12    0.000    0.000   10.714    0.893 fixtures.py:261(with_plugins)
       48    0.000    0.000   10.682    0.223 fixtures.py:553(getfixturevalue)
   115/48    0.000    0.000   10.682    0.223 fixtures.py:568(_get_active_fixturedef)
        6    0.000    0.000   10.682    1.780 runner.py:152(pytest_runtest_setup)
        6    0.000    0.000   10.682    1.780 runner.py:475(setup)
    42/24    0.000    0.000   10.681    0.445 fixtures.py:596(_compute_fixture_value)
        6    0.000    0.000   10.681    1.780 python.py:1763(setup)

Using the fixture generates 20 millon extra function calls (probably builtins.next). It also points to update_config and plugins_update consuming 13 seconds (of the total 17)

While navigating with snakeviz: