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:
- Run any test cases with debug level log
- 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)
```
Description
This issue is introduced by commit 077f148. In this commit, it introduced some new lines in function pytest_generate_tests:
It tries to get testbed info here. However, get testbed info takes many time. I added some debug log.
The debug code:
The logs:
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:
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: