AdamWill
commented
7 months ago Detailed profile data...here's the "before" (everything down to ~30 seconds cumtime):
=============== 1607 passed, 4213 warnings in 727.64s (0:12:07) ================
957433694 function calls (954028290 primitive calls) in 727.034 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
2383/1 0.141 0.000 728.168 728.168 {built-in method builtins.exec}
1 0.000 0.000 728.168 728.168 <string>:1(<module>)
1 0.000 0.000 728.168 728.168 <frozen runpy>:201(run_module)
1 0.000 0.000 728.074 728.074 <frozen runpy>:65(_run_code)
2 0.000 0.000 728.074 364.037 __main__.py:1(<module>)
1 0.000 0.000 728.074 728.074 __init__.py:185(console_main)
1 0.000 0.000 728.074 728.074 __init__.py:135(main)
46770/72 0.053 0.000 728.050 10.112 _manager.py:106(_hookexec)
46770/72 0.660 0.000 728.050 10.112 _callers.py:27(_multicall)
40814/2 0.099 0.000 728.049 364.024 _hooks.py:479(__call__)
1 0.000 0.000 727.670 727.670 main.py:317(pytest_cmdline_main)
1 0.000 0.000 727.670 727.670 main.py:258(wrap_session)
1 0.000 0.000 727.610 727.610 main.py:321(_main)
5120 0.038 0.000 720.010 0.141 runner.py:318(from_call)
1 0.008 0.008 715.523 715.523 main.py:338(pytest_runtestloop)
1607 0.014 0.000 715.131 0.445 runner.py:111(pytest_runtest_protocol)
1607 0.017 0.000 714.581 0.445 runner.py:119(runtestprotocol)
4821 0.037 0.000 714.557 0.148 runner.py:219(call_and_report)
4821 0.025 0.000 713.653 0.148 runner.py:247(call_runtest_hook)
4821 0.012 0.000 713.506 0.148 runner.py:262(<lambda>)
436352/153753 0.423 0.000 620.440 0.004 {built-in method builtins.next}
1607 0.005 0.000 606.919 0.378 runner.py:155(pytest_runtest_setup)
1607 0.016 0.000 606.894 0.378 runner.py:478(setup)
1606 0.002 0.000 606.864 0.378 python.py:1794(setup)
1607 0.012 0.000 606.862 0.378 fixtures.py:561(_fillfixtures)
6365 0.009 0.000 606.845 0.095 fixtures.py:568(getfixturevalue)
11045/6365 0.051 0.000 606.836 0.095 fixtures.py:592(_get_active_fixturedef)
4758 0.043 0.000 606.759 0.128 fixtures.py:620(_compute_fixture_value)
4758 0.022 0.000 606.604 0.127 fixtures.py:1041(execute)
2830 0.012 0.000 606.417 0.214 python.py:889(xunit_setup_method_fixture)
2818 0.017 0.000 606.399 0.215 python.py:770(_call_with_optional_argument)
3144 0.014 0.000 606.349 0.193 fixtures.py:1108(pytest_fixture_setup)
3144 0.025 0.000 606.246 0.193 fixtures.py:886(call_fixture_func)
1404 0.150 0.000 588.807 0.419 base.py:225(_setup_method)
1403 0.005 0.000 588.403 0.419 base.py:400(setup_method)
1403 0.005 0.000 588.403 0.419 base.py:400(setup_method)
1447 0.010 0.000 485.653 0.336 paster.py:33(get_appsettings)
1447 0.007 0.000 478.994 0.331 common.py:18(get_config_loader)
1447 0.013 0.000 478.987 0.331 loaders.py:87(get_loader)
1447 0.040 0.000 478.799 0.331 loaders.py:125(find_loaders)
2894 3.084 0.001 475.684 0.164 loaders.py:169(_iter_ep_in_dists)
503565 2.162 0.000 416.819 0.001 __init__.py:436(metadata)
503565 1.197 0.000 352.753 0.001 __init__.py:31(message_from_string)
503595 1.879 0.000 351.401 0.001 parser.py:56(parsestr)
503595 1.942 0.000 349.522 0.001 parser.py:41(parse)
725008 1.142 0.000 321.407 0.000 feedparser.py:171(feed)
1228603 5.390 0.000 315.818 0.000 feedparser.py:176(_call_parse)
1228603 72.685 0.000 310.428 0.000 feedparser.py:216(_parsegen)
101694781 43.864 0.000 115.260 0.000 feedparser.py:127(__next__)
1607 0.010 0.000 103.131 0.064 runner.py:160(pytest_runtest_call)
1606 0.005 0.000 102.677 0.064 python.py:1790(runtest)
1606 0.026 0.000 102.627 0.064 python.py:187(pytest_pyfunc_call)
252 0.007 0.000 96.678 0.384 test_models.py:70(setup_method)
946/872 0.030 0.000 77.405 0.089 mock.py:1382(patched)
503595 32.575 0.000 76.017 0.000 feedparser.py:469(_parse_headers)
101694781 59.435 0.000 71.396 0.000 feedparser.py:77(readline)
8243 0.019 0.000 67.955 0.008 base.py:2602(commit)
7076 0.060 0.000 67.694 0.010 base.py:2719(_do_commit)
7076 0.014 0.000 67.625 0.010 base.py:2694(_connection_commit_impl)
7076 0.051 0.000 67.611 0.010 base.py:1123(_commit_impl)
7076 0.028 0.000 67.484 0.010 default.py:694(do_commit)
7076 67.447 0.010 67.447 0.010 {method 'commit' of 'sqlite3.Connection' objects}
2808 0.019 0.000 60.660 0.022 base.py:3236(_run_ddl_visitor)
314568/63082 0.759 0.000 59.942 0.001 state_changes.py:95(_go)
980787 5.025 0.000 57.869 0.000 __init__.py:810(read_text)
13206/7610 0.022 0.000 57.424 0.008 <string>:1(commit)
13206/7610 0.182 0.000 57.378 0.008 session.py:1249(commit)
4626 0.011 0.000 57.301 0.012 session.py:1933(commit)
1152 0.091 0.000 45.741 0.040 base.py:154(populate)
980808 2.016 0.000 43.081 0.000 pathlib.py:1023(read_text)
95544/94628 0.148 0.000 39.533 0.000 contextlib.py:141(__exit__)and here's the "after" (same set of stuff):
=============== 1607 passed, 4213 warnings in 225.19s (0:03:45) ================
151732805 function calls (148226263 primitive calls) in 224.914 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
2383/1 0.144 0.000 225.648 225.648 {built-in method builtins.exec}
1 0.000 0.000 225.648 225.648 <string>:1(<module>)
1 0.000 0.000 225.648 225.648 <frozen runpy>:201(run_module)
1 0.000 0.000 225.554 225.554 <frozen runpy>:65(_run_code)
2 0.000 0.000 225.554 112.777 __main__.py:1(<module>)
1 0.000 0.000 225.554 225.554 __init__.py:185(console_main)
1 0.000 0.000 225.554 225.554 __init__.py:135(main)
46770/72 0.044 0.000 225.539 3.132 _manager.py:106(_hookexec)
46770/72 0.562 0.000 225.539 3.132 _callers.py:27(_multicall)
40814/2 0.086 0.000 225.537 112.769 _hooks.py:479(__call__)
1 0.000 0.000 225.213 225.213 main.py:317(pytest_cmdline_main)
1 0.000 0.000 225.213 225.213 main.py:258(wrap_session)
1 0.000 0.000 225.154 225.154 main.py:321(_main)
5120 0.033 0.000 216.362 0.042 runner.py:318(from_call)
1 0.007 0.007 211.608 211.608 main.py:338(pytest_runtestloop)
1607 0.012 0.000 211.271 0.131 runner.py:111(pytest_runtest_protocol)
1607 0.014 0.000 210.798 0.131 runner.py:119(runtestprotocol)
4821 0.032 0.000 210.777 0.044 runner.py:219(call_and_report)
4821 0.021 0.000 210.010 0.044 runner.py:247(call_runtest_hook)
4821 0.010 0.000 209.885 0.044 runner.py:262(<lambda>)
433109/154717 0.325 0.000 130.395 0.001 {built-in method builtins.next}
1607 0.004 0.000 119.200 0.074 runner.py:155(pytest_runtest_setup)
1607 0.014 0.000 119.178 0.074 runner.py:478(setup)
1606 0.002 0.000 119.152 0.074 python.py:1794(setup)
1607 0.010 0.000 119.150 0.074 fixtures.py:561(_fillfixtures)
6365 0.007 0.000 119.135 0.019 fixtures.py:568(getfixturevalue)
11045/6365 0.042 0.000 119.128 0.019 fixtures.py:592(_get_active_fixturedef)
4758 0.038 0.000 119.064 0.025 fixtures.py:620(_compute_fixture_value)
4758 0.017 0.000 118.927 0.025 fixtures.py:1041(execute)
2830 0.010 0.000 118.748 0.042 python.py:889(xunit_setup_method_fixture)
2818 0.014 0.000 118.733 0.042 python.py:770(_call_with_optional_argument)
3144 0.012 0.000 118.711 0.038 fixtures.py:1108(pytest_fixture_setup)
3144 0.021 0.000 118.624 0.038 fixtures.py:886(call_fixture_func)
1404 0.103 0.000 100.333 0.071 base.py:226(_setup_method)
1403 0.004 0.000 100.101 0.071 base.py:406(setup_method)
1607 0.009 0.000 87.758 0.055 runner.py:160(pytest_runtest_call)
1606 0.005 0.000 87.484 0.054 python.py:1790(runtest)
1606 0.024 0.000 87.443 0.054 python.py:187(pytest_pyfunc_call)
946/872 0.024 0.000 64.517 0.074 mock.py:1382(patched)
8243 0.015 0.000 61.743 0.007 base.py:2602(commit)
7076 0.048 0.000 61.523 0.009 base.py:2719(_do_commit)
7076 0.011 0.000 61.467 0.009 base.py:2694(_connection_commit_impl)
7076 0.042 0.000 61.456 0.009 base.py:1123(_commit_impl)
7076 0.022 0.000 61.350 0.009 default.py:694(do_commit)
7076 61.322 0.009 61.322 0.009 {method 'commit' of 'sqlite3.Connection' objects}
314594/63021 0.668 0.000 54.981 0.001 state_changes.py:95(_go)
13206/7610 0.019 0.000 53.437 0.007 <string>:1(commit)
13206/7610 0.156 0.000 53.397 0.007 session.py:1249(commit)
4626 0.009 0.000 53.333 0.012 session.py:1933(commit)
2808 0.015 0.000 51.180 0.018 base.py:3236(_run_ddl_visitor)
1152 0.075 0.000 40.011 0.035 base.py:155(populate)
95652/94736 0.127 0.000 33.815 0.000 contextlib.py:141(__exit__)
I ran the server test suite through cProfile and found it was spending a whole lot of time re-reading settings from testing.ini (that's where BODHI_CONFIG points) every time a test ran. This tweaks it to only read the settings from the file one time (but it will still apply them before every test runs, since some of the tests modify the config dict and we don't want those changes to leak into other tests).
In my test, this reduces the time to run the whole test suite from 727 seconds to 224 seconds.