ACL tests are taking a long time to run in master

[arista-nwolfe]

Issue Description

The sonic-mgmt ACL tests have increased in runtime duration significantly between the 202205 to master branch.

Results you see

Here are a few of the test runtime outputs on master:

12/04/2024 **23:20:08** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_ingress_unmatched_blocked[ipv4-ingress-downlink->uplink-nfc407-5-default-no_vlan] setup  ====================
…
12/04/2024 23:27:57 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_ingress_unmatched_blocked[ipv4-ingress-downlink->uplink-nfc407-5-default-no_vlan] teardown ====================
12/04/2024 **23:27:57** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_egress_unmatched_forwarded[ipv4-ingress-downlink->uplink-nfc407-7-default-no_vlan] setup  ====================
…
12/04/2024 23:32:30 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_egress_unmatched_forwarded[ipv4-ingress-downlink->uplink-nfc407-7-default-no_vlan] teardown ====================
12/04/2024 **23:32:30** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_source_ip_match_forwarded[ipv4-ingress-downlink->uplink-nfc407-5-default-no_vlan] setup  ====================
…
12/04/2024 23:37:02 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_source_ip_match_forwarded[ipv4-ingress-downlink->uplink-nfc407-5-default-no_vlan] teardown ====================
12/04/2024 **23:37:02** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_rules_priority_forwarded[ipv4-ingress-downlink->uplink-nfc407-7-default-no_vlan] setup  ====================
…
12/04/2024 23:41:50 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_rules_priority_forwarded[ipv4-ingress-downlink->uplink-nfc407-7-default-no_vlan] teardown ====================
12/04/2024 **23:41:50** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_rules_priority_dropped[ipv4-ingress-downlink->uplink-nfc407-default-no_vlan] setup  ====================

Results you expected to see

Here are those same test runtime outputs on 202205:

15/03/2024 **22:52:42** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_ingress_unmatched_blocked[ipv4-ingress-downlink->uplink-default-no_vlan] setup  ====================
…
15/03/2024 22:58:35 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_ingress_unmatched_blocked[ipv4-ingress-downlink->uplink-default-no_vlan] teardown ====================
15/03/2024 **22:58:35** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_egress_unmatched_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] setup  ====================
…
15/03/2024 22:58:35 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_egress_unmatched_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] teardown ====================
15/03/2024 **22:58:35** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_source_ip_match_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] setup  ====================
…
15/03/2024 22:58:35 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_source_ip_match_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] teardown ====================
15/03/2024 **22:58:35** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_rules_priority_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] setup  ====================
…
15/03/2024 22:58:35 __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_rules_priority_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] teardown ====================
15/03/2024 **22:58:35** __init__._log_sep_line                   L0170 INFO   | ==================== acl/test_acl.py::TestBasicAcl::test_rules_priority_dropped[ipv4-ingress-downlink->uplink-default-no_vlan] setup  ====================

Note the amount of time between the first two testlets is similar but then subsequent tests on 202205 would take 1s while on master they take ~5 minutes each.

Also note that test_egress_unmatched_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] is SKIPPED but it still takes ~5 minutes on master so this suggests it maybe the test fixtures which are consuming so much time on master.

Is it platform specific

generic

Relevant log output

No response

Output of show version

No response

Attach files (if any)

No response

[vperumal]

@arista-nwolfe, the time is increased because each test is repeating all the fixtures, i.e. acl tabl creation, setup, populate_vlan_arp_entries acl rule creation and then teardown of each of the above fixtures, hence increasing the total time for each test case.
Master run

30/04/2024 22:16:04 init._fixture_generator_decorator L0081 INFO | -------------------- fixture setup setup starts --------------------
30/04/2024 22:16:21 init._fixture_generator_decorator L0085 INFO | -------------------- fixture setup setup ends --------------------
30/04/2024 22:16:21 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_table setup starts --------------------
30/04/2024 22:18:26 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_table setup ends --------------------
30/04/2024 22:18:26 init._fixture_generator_decorator L0081 INFO | -------------------- fixture populate_vlan_arp_entries setup starts --------------------
30/04/2024 22:18:26 init._fixture_generator_decorator L0085 INFO | -------------------- fixture populate_vlan_arp_entries setup ends --------------------
30/04/2024 22:18:26 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
30/04/2024 22:20:33 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------
30/04/2024 22:20:45 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_rules teardown starts --------------------
30/04/2024 22:21:09 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_rules teardown ends --------------------
30/04/2024 22:21:09 init._fixture_generator_decorator L0093 INFO | -------------------- fixture populate_vlan_arp_entries teardown starts --------------------
30/04/2024 22:21:09 init._fixture_generator_decorator L0102 INFO | -------------------- fixture populate_vlan_arp_entries teardown ends --------------------
30/04/2024 22:21:09 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_table teardown starts --------------------
30/04/2024 22:23:15 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_table teardown ends --------------------
30/04/2024 22:23:15 init._fixture_generator_decorator L0093 INFO | -------------------- fixture setup teardown starts --------------------
30/04/2024 22:23:16 init._fixture_generator_decorator L0102 INFO | -------------------- fixture setup teardown ends --------------------
30/04/2024 22:23:16 init._fixture_generator_decorator L0081 INFO | -------------------- fixture setup setup starts --------------------
30/04/2024 22:23:26 init._fixture_generator_decorator L0085 INFO | -------------------- fixture setup setup ends --------------------
30/04/2024 22:23:26 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_table setup starts --------------------
30/04/2024 22:25:32 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_table setup ends --------------------
30/04/2024 22:25:32 init._fixture_generator_decorator L0081 INFO | -------------------- fixture populate_vlan_arp_entries setup starts --------------------
30/04/2024 22:25:32 init._fixture_generator_decorator L0085 INFO | -------------------- fixture populate_vlan_arp_entries setup ends --------------------
30/04/2024 22:25:32 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
30/04/2024 22:27:38 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------
30/04/2024 22:27:46 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_rules teardown starts --------------------
30/04/2024 22:28:10 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_rules teardown ends --------------------
30/04/2024 22:28:10 init._fixture_generator_decorator L0093 INFO | -------------------- fixture populate_vlan_arp_entries teardown starts --------------------
30/04/2024 22:28:10 init._fixture_generator_decorator L0102 INFO | -------------------- fixture populate_vlan_arp_entries teardown ends --------------------
30/04/2024 22:28:10 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_table teardown starts --------------------
30/04/2024 22:30:16 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_table teardown ends --------------------
30/04/2024 22:30:16 init._fixture_generator_decorator L0093 INFO | -------------------- fixture setup teardown starts --------------------
30/04/2024 22:30:18 init._fixture_generator_decorator L0102 INFO | -------------------- fixture setup teardown ends --------------------
30/04/2024 22:30:18 init._fixture_generator_decorator L0081 INFO | -------------------- fixture setup setup starts --------------------
30/04/2024 22:30:29 init._fixture_generator_decorator L0085 INFO | -------------------- fixture setup setup ends --------------------

vs
202305 - wherein it was once per paramertization value so once per 25 testcases

16/03/2024 02:06:34 init._fixture_generator_decorator L0081 INFO | -------------------- fixture setup setup starts --------------------
16/03/2024 02:06:50 init._fixture_generator_decorator L0085 INFO | -------------------- fixture setup setup ends --------------------
16/03/2024 02:06:50 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_table setup starts --------------------
16/03/2024 02:09:09 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_table setup ends --------------------
16/03/2024 02:09:09 init._fixture_generator_decorator L0081 INFO | -------------------- fixture populate_vlan_arp_entries setup starts --------------------
16/03/2024 02:09:09 init._fixture_generator_decorator L0085 INFO | -------------------- fixture populate_vlan_arp_entries setup ends --------------------
16/03/2024 02:09:09 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
16/03/2024 02:11:22 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------
16/03/2024 02:12:25 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_rules teardown starts --------------------
16/03/2024 02:12:56 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_rules teardown ends --------------------
16/03/2024 02:12:56 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
16/03/2024 02:15:23 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------
16/03/2024 02:16:26 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_rules teardown starts --------------------
16/03/2024 02:16:55 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_rules teardown ends --------------------
16/03/2024 02:16:55 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
16/03/2024 03:07:11 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------
16/03/2024 03:08:11 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_rules teardown starts --------------------
16/03/2024 03:08:33 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_rules teardown ends --------------------
16/03/2024 03:08:33 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
16/03/2024 03:23:41 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------
16/03/2024 03:24:41 init._fixture_generator_decorator L0093 INFO | -------------------- fixture acl_rules teardown starts --------------------
16/03/2024 03:25:06 init._fixture_generator_decorator L0102 INFO | -------------------- fixture acl_rules teardown ends --------------------
16/03/2024 03:25:06 init._fixture_generator_decorator L0081 INFO | -------------------- fixture acl_rules setup starts --------------------
16/03/2024 03:27:11 init._fixture_generator_decorator L0085 INFO | -------------------- fixture acl_rules setup ends --------------------

Scriptwise there is no change, but somehow pytest fixtures are having issues. FYI @abdosi @rajendrat @anamehra

[arista-nwolfe]

@vperumal thanks for the details, do you happen to know why this change was made to run all fixtures on each test instead of once per paramertization? Or do you have a link to the PR which made that change?

[yejianquan]

Assign to @cyw233 as discussed

[arista-nwolfe]

I noticed that the parameters of the tests changed between master and 202305.

Master:
ipv4-ingress-downlink->uplink-nfc407-5-default-no_vlan

202305:
ipv4-ingress-downlink->uplink-default-no_vlan

I reverted this PR which appears to have added that extra nfc407-5
#11614

After that I see the individual tests don't run the long running fixtures acl_tables and acl_rules between each test

acl/test_acl.py::TestBasicAcl::test_source_ip_match_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] setup
pytest_fixture_setup: fixture_name=direction, time=0.000380
pytest_fixture_setup: fixture_name=get_src_port, time=0.000502
acl/test_acl.py::TestBasicAcl::test_source_ip_match_forwarded[ipv4-ingress-downlink->uplink-default-no_vlan] call

[vperumal]

@arista-nwolfe - Yes, It looks like that is the cause. The extra nfc407-5 is the dut parameterization. But the root cause as to why it causes this issue seems to be an issue in pytest - pytest-dev/pytest#12146. They think this may fix it - pytest-dev/pytest#11257 but it is still not merged or confirmed yet.

[arista-nwolfe]

Ah good find @vperumal, thanks for the reference

[cyw233]

Hey @arista-nwolfe @vperumal, sorry I was late to the party. It seems like the logs are fine on my end, for example, there are only 2 fixture acl_table setup starts logs, one for IPv4 and the other one for IPv6. May I ask how to reproduce this issue, please?

[vperumal]

Hi @cyw233 - the issue is reproducible when you have multi-duts - For e.g. T2 profile. ACL script runs on the whole chassis, it doesn't repeat the test for each DUT. The tests are repeated for other parameters, direction, v4/v6 etc. The change introduced in #11614 causes the test to run on each DUT, which in turn causes individual fixtures to repeat. Any script similar to ACL will face the same problem. we will need to revert #11614 to fix this issue.

[cyw233]

Thank you @vperumal for the info! Let me talk to the author of the PR and find the best way to resolve this. Cheers.

[cyw233]

Had a discussion with @liuh-80 and he will take a look at the changes in #11614 and see how to bypass this issue.

[arista-nwolfe]

@liuh-80 @cyw233 does #12824 fix this issue?

[cyw233]

Hey @arista-nwolfe , yes that PR should fix this issue. Can you please confirm on your end as well? Thanks!

[arista-nwolfe]

@patrickmacarthur confirmed that this PR fixed this issue. Thanks!