Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

pytest_generate_tests in tests/conftest.py takes much more time than before #2790

Closed
Junchao-Mellanox opened this issue Jan 12, 2021 · 6 comments

Comments

@Junchao-Mellanox
Copy link
Contributor

Junchao-Mellanox commented Jan 12, 2021

Description

This issue is introduced by commit 077f148. In this commit, it introduced some new lines in function pytest_generate_tests:

def pytest_generate_tests(metafunc):
    # The topology always has atleast 1 dut	    # The topology always has atleast 1 dut
    dut_indices = [0]	    dut_indices = [0]

    tbname, testbedinfo = get_tbinfo(metafunc)
    duts_in_testbed = testbedinfo["duts"]

It tries to get testbed info here. However, get testbed info takes many time. I added some debug log.

The debug code:

def pytest_generate_tests(metafunc):
    # The topology always has atleast 1 dut
    t1 = time.time()
    dut_indices = [0]
    tbname, testbedinfo = get_tbinfo(metafunc)
    t2 = time.time()
    logging.info('get tb info takes {}'.format(t2-t1))
    ...
    # at the end of this function
    t3 = time.time()
    logging.info('generate test takes {}'.format(t3 - t2))

The logs:

09:31:34 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.32364201546
09:31:34 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000878095626831
09:31:34 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:31:43 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.42963409424
09:31:43 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000459909439087
09:31:43 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:31:53 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.65246009827
09:31:53 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000452995300293
09:31:53 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:02 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.41860485077
09:32:02 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000477075576782
09:32:02 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:12 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.54106998444
09:32:12 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000458955764771
09:32:12 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:21 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.53165388107
09:32:21 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000458002090454
09:32:21 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:31 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.46508693695
09:32:31 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000452041625977
09:32:31 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:41 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.56296014786
09:32:41 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000479936599731
09:32:41 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:50 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.57247781754
09:32:50 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000463008880615
09:32:50 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:32:59 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.39605808258
09:32:59 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000459909439087
09:32:59 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:33:09 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.46025586128
09:33:09 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000463962554932
09:33:09 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:33:18 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.4327878952
09:33:18 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000454902648926
09:33:18 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:33:28 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.4818148613
09:33:28 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000462055206299
09:33:28 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:33:37 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.61958408356
09:33:37 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000456094741821
09:33:37 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:33:47 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.38003921509
09:33:47 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000452995300293
09:33:47 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:33:56 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.43004393578
09:33:56 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000452041625977
09:33:56 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:34:06 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.38197898865
09:34:06 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000454187393188
09:34:06 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:34:15 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.72663092613
09:34:15 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000468015670776
09:34:15 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:34:25 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.71188187599
09:34:25 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000474214553833
09:34:25 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:34:35 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.82909107208
09:34:35 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000453948974609
09:34:35 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
09:34:44 INFO conftest.py:pytest_generate_tests:787: get tb info takes 9.37812399864
09:34:44 INFO conftest.py:pytest_generate_tests:835: generate test takes 0.000472068786621
09:34:44 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called

As the log shows, get testbed info takes 9 seconds for each call, and the rest of the function only takes no more than 1 ms. Since this function is called many times before the real test, it introduces a 3 minutes delay for each test cases. We don't have to get the testbed info again and again. We need optimize this.

Steps to reproduce the issue:

  1. Run any test cases with debug level log
  2. The test case will block at pytest_generate_tests for a few minutes

Describe the results you received:

pytest_generate_tests takes 3 minutes

Describe the results you expected:

pytest_generate_tests should take no more than 15 seconds

Additional information you deem important:

**Output of `show version`:**

```
(paste your output here)
```

**Attach debug file `sudo generate_dump`:**

```
(paste your output here)
```
@sanmalho-git
Copy link
Contributor

Before this commit, TestbedInfo object was being created in every generate_param_* method defined in conftest.py. I optimized it to create the TestbedInfo only once. However, before the generate_param_* methods were being called only if we had a 'enum_*" parameter in the fixture/test case.

@Junchao-Mellanox - I added your debug code and ran pytest with '--log-level debug --log-cli-level debug' and see that get_tbinfo is taking only ~0.8 secs. What flags are you turning on when you say run with 'debug log level'

import time
def pytest_generate_tests(metafunc):
    # The topology always has atleast 1 dut
    dut_indices = [0]
    t1 = time.time()
    tbname, testbedinfo = get_tbinfo(metafunc)
    t2 = time.time()
    logging.info('get tb info takes {}'.format(t2 - t1))
    ...

Run

johnvar@b246ffeda779:/data/sonic-mgmt/ansible$ py.test -rA ../tests/bgp/test_bgp_fact.py --inventory /data/sonic-mgmt/ansible/westford_hw_inventory,/data/sonic-mgmt/ansible/nokia_veos --host-pattern ixr_hr_chassis1 --testbed ixr_hr_chassis1-t2 --testbed_file /data/sonic-mgmt/ansible/testbed.csv --log-level debug --log-cli-level debug
/usr/local/lib/python2.7/dist-packages/ansible/parsing/vault/__init__.py:44: CryptographyDeprecationWarning: Python 2 is no longer supported by the Python core team. Support for it is now deprecated in cryptography, and will be removed in a future release.
  from cryptography.exceptions import InvalidSignature
============================================================================================ test session starts =============================================================================================
platform linux2 -- Python 2.7.17, pytest-4.6.5, py-1.9.0, pluggy-0.13.1

------------------------------------------------------------------------------------------- live log sessionstart --------------------------------------------------------------------------------------------
14:51:11 DEBUG plugin.py:pytest_report_header:168: pytest_report_header() called
-------------------------------------------------------------------------------------------- live log collection ---------------------------------------------------------------------------------------------
14:51:12 INFO conftest.py:pytest_generate_tests:775: get tb info takes 0.845477104187

@sanmalho-git
Copy link
Contributor

A fix for this issue (to be compatible with how the behavior was before) where we were creating TestbedInfo only if the test had 'enum_*' parameterized:

def pytest_generate_tests(metafunc):
    # The topology always has atleast 1 dut
    dut_indices = [0]

    def _get_duts_in_testbed(request):
        tbname, testbedinfo = get_tbinfo(metafunc)
        duts_in_testbed = testbedinfo["duts"]
        return tbname, duts_in_testbed

    # Enumerators ("enum_dut_index", "enum_dut_hostname", "rand_one_dut_hostname") are mutually exclusive
    if "enum_dut_index" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        dut_indices = generate_params_dut_index(duts_in_testbed, tbname)
        metafunc.parametrize("enum_dut_index", dut_indices, scope="module")
    elif "enum_dut_hostname" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        dut_hostnames = generate_params_dut_hostname(duts_in_testbed, tbname)
        metafunc.parametrize("enum_dut_hostname", dut_hostnames, scope="module")
    elif "enum_supervisor_dut_hostname" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        supervisor_hosts = generate_params_supervisor_hostname(metafunc, duts_in_testbed, tbname)
        metafunc.parametrize("enum_supervisor_dut_hostname", supervisor_hosts, scope="module")
    elif "enum_frontend_dut_hostname" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        frontend_hosts = generate_params_frontend_hostname(metafunc, duts_in_testbed, tbname)
        metafunc.parametrize("enum_frontend_dut_hostname", frontend_hosts, scope="module")
    elif "enum_rand_one_per_hwsku_frontend_hostname" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        frontend_hosts_per_hwsku = generate_params_frontend_hostname_rand_per_hwsku(metafunc, duts_in_testbed, tbname)
        metafunc.parametrize("enum_rand_one_per_hwsku_frontend_hostname", frontend_hosts_per_hwsku, scope="module")


    if "enum_asic_index" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        metafunc.parametrize("enum_asic_index",
                             generate_param_asic_index(metafunc, duts_in_testbed, dut_indices, ASIC_PARAM_TYPE_ALL))
    if "enum_frontend_asic_index" in metafunc.fixturenames:
        tbname, duts_in_testbed = _get_duts_in_testbed(metafunc)
        metafunc.parametrize("enum_frontend_asic_index",
                             generate_param_asic_index(metafunc, duts_in_testbed, dut_indices, ASIC_PARAM_TYPE_FRONTEND))
   .
   .

@yxieca @wangxin @Junchao-Mellanox - if this fix is acceptable, I will push it out.

@sanmalho-git
Copy link
Contributor

If we are ok with global variable for duts_in_testbed, then a better solution

_duts_in_testbed = None
def pytest_generate_tests(metafunc):
    # The topology always has atleast 1 dut
    dut_indices = [0]
    global _duts_in_testbed
    tbname = None
    if _duts_in_testbed is None:
        tbname, testbedinfo = get_tbinfo(metafunc)
        _duts_in_testbed = testbedinfo["duts"]

    # Enumerators ("enum_dut_index", "enum_dut_hostname", "rand_one_dut_hostname") are mutually exclusive
    if "enum_dut_index" in metafunc.fixturenames:
        dut_indices = generate_params_dut_index(_duts_in_testbed, tbname)
        metafunc.parametrize("enum_dut_index", dut_indices, scope="module")
    elif "enum_dut_hostname" in metafunc.fixturenames:
        dut_hostnames = generate_params_dut_hostname(_duts_in_testbed, tbname)
        metafunc.parametrize("enum_dut_hostname", dut_hostnames, scope="module")
    elif "enum_supervisor_dut_hostname" in metafunc.fixturenames:
        supervisor_hosts = generate_params_supervisor_hostname(metafunc, _duts_in_testbed, tbname)
        metafunc.parametrize("enum_supervisor_dut_hostname", supervisor_hosts, scope="module")
    elif "enum_frontend_dut_hostname" in metafunc.fixturenames:
        frontend_hosts = generate_params_frontend_hostname(metafunc, _duts_in_testbed, tbname)
        metafunc.parametrize("enum_frontend_dut_hostname", frontend_hosts, scope="module")
    elif "enum_rand_one_per_hwsku_frontend_hostname" in metafunc.fixturenames:
        frontend_hosts_per_hwsku = generate_params_frontend_hostname_rand_per_hwsku(metafunc, _duts_in_testbed, tbname)
        metafunc.parametrize("enum_rand_one_per_hwsku_frontend_hostname", frontend_hosts_per_hwsku, scope="module")


    if "enum_asic_index" in metafunc.fixturenames:
        metafunc.parametrize("enum_asic_index",
                             generate_param_asic_index(metafunc, _duts_in_testbed, dut_indices, ASIC_PARAM_TYPE_ALL))
    if "enum_frontend_asic_index" in metafunc.fixturenames:
        metafunc.parametrize("enum_frontend_asic_index",
                             generate_param_asic_index(metafunc, _duts_in_testbed, dut_indices, ASIC_PARAM_TYPE_FRONTEND))

@Junchao-Mellanox
Copy link
Contributor Author

Hi, I verified both of the fix, all works.

@liat-grozovik
Copy link
Collaborator

@sanmalho-git where do we stands with this PR? Is something blocking you or we can move on?

@sanmalho-git
Copy link
Contributor

We have a PR #2811 - Optimizing dut selection fixtures in pytest_generate_tests. This solution works, but am waiting on another PR for caching from @wangxin to push before changing the code to use caching instead of global variables.

sanmalho-git added a commit to sanmalho-git/sonic-mgmt that referenced this issue Feb 1, 2021
This is a fix for issue sonic-net#2790 - pytest_generate_tests in tests/conftest.py takes much more time than before

The reason for the issue was that creating the TestbedInfo takes 1-9 seconds, and was part of
pytest_generate_tests. Since pytest_generate_tests is called for all the tests/fixtures, this was
adding a long time when trying to execute many tests.

For some of the other dut selection fixtures we were also getting variables for the duts
from the inventory files - which also takes a long time - adding to the execution delay.

To fix is to use create the TestbedInfo and getting the variables from the inventory files
for all the DUTS only once - by storing it in global variables. If these global variables
are not set, then we would set them. Thus, creating TestbedInfo and getting variables only once
per pytest run
wangxin pushed a commit that referenced this issue Feb 6, 2021
…xtures (#2811)

What is the motivation for this PR?
pytest_generate_tests dynamically adds enum_* fixtures that select DUTs on which the tests are to be parameterized. In order to select the DUTs on which the tests are to run, we need to get the TestbedInfo and also all variables defined in the inventory file for each DUT. These operations are time consuming - like creating TestbedInfo taking 1-9 seconds, and getting variables from inventory taking 3-5 seconds.

pytest_generate_tests is called for all the tests/fixtures that needs to run in a pytest session. This was adding a long time when trying to execute many tests.

This issue was reported in issue #2790 - pytest_generate_tests in tests/conftest.py takes much more time than before

How did you do it?
To fix this, we need to create the TestbedInfo only once, store it, and then use the stored value in the next execution of pytest_generate_tests, rather than re-creating TestbedInfo. Similary, the variables for all the DUTs in the testbed should be read once from the inventory files, stored, and the re-used in the next execution of pytest_generate_tests.

PR #2789 Added caching capability to store any facts using pickle.
PR #2856 added caching capability for TestbedInfo
PR #2873 added caching capability for variables for DUTs in the inventory files.

We use the cached TestbedInfo and DUT variables in the selection of DUTs in pytest_generate_tests.

How did you verify/test it?
Ran tests that use the dut selection fixtures and validated that the delay is seen only once, and not in every call to pytest_generate_tests.
Validated the execution time reduced significantly when using caching when executing iface_namingmode test cases which have ~30 tests.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants