Hi there,
I just updated our sanic version from 22.12.0 to 23.6.0 in order to get the fix for Request.get_current() not working in ASGI context. However, this upgrade caused a massive delay in application startup (for us 20-30 seconds). To the extent that sanic would kill and restart workers, so I had to increase the threshold as a workaround.
We have around 500 routes, and I first thought maybe one of the extensions, namely openapi v3, is the cuprit. However, after trying everything possible (and disabling, even removing the docs completely) I noticed just the presence of sanic-ext is enough to have the delay.
Running sanic in single process or as ASGI application had no effect, except making debugging slightly easier.
So to sum up, the main process waits for workers to come up and workers need over 22 seconds to acknowledge they are up. This does not happen with 22.12.0 release.
I’m at loss what is happening and would appreciate any hints.
Edit:
I’m using Python 3.11 and the delay appears to be independent of my Linux distro and happens on different Linux environments. By removing sanic-ext the delay immediately disappears.
Below is the output of cProfile running sanic in single process mode:
99810732 function calls (88673304 primitive calls) in 62.608 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
2726/1 0.025 0.000 62.643 62.643 {built-in method builtins.exec}
1 0.000 0.000 62.643 62.643 <string>:1(<module>)
1 0.000 0.000 62.643 62.643 <frozen runpy>:201(run_module)
1 0.000 0.000 62.406 62.406 <frozen runpy>:65(_run_code)
1 0.000 0.000 62.406 62.406 __main__.py:1(<module>)
1 0.000 0.000 62.400 62.400 __main__.py:9(main)
1 0.000 0.000 62.398 62.398 app.py:79(run)
1 0.000 0.000 60.438 60.438 startup.py:914(serve_single)
1 0.000 0.000 60.433 60.433 serve.py:23(worker_serve)
1 0.000 0.000 60.433 60.433 runners.py:161(_serve_http_1)
7 0.001 0.000 49.808 7.115 {method 'run_until_complete' of 'uvloop.loop.Loop' objects}
4 0.000 0.000 49.582 12.396 app.py:1746(_server_event)
5 0.000 0.000 49.582 9.916 signals.py:188(dispatch)
5 0.000 0.000 49.581 9.916 signals.py:128(_dispatch)
9 0.000 0.000 49.581 5.509 app.py:1306(_listener)
1219 0.017 0.000 48.490 0.040 routes.py:102(decorator)
1 0.017 0.017 48.295 48.295 methods.py:69(_add_handlers)
675 0.006 0.000 47.751 0.071 routes.py:197(add_route)
1213 0.012 0.000 47.704 0.039 app.py:523(_apply_route)
1754681/29321 0.465 0.000 47.440 0.002 {built-in method builtins.next}
2458 0.006 0.000 47.409 0.019 app.py:1662(amend)
753995/11099 0.411 0.000 47.265 0.004 contextlib.py:141(__exit__)
673 0.001 0.000 47.259 0.070 app.py:1691(signalize)
673 0.199 0.000 47.257 0.070 signals.py:247(finalize)
676 0.467 0.001 45.797 0.068 router.py:302(finalize)
676 0.031 0.000 43.280 0.064 router.py:382(_render)
2317643/1238 1.686 0.000 16.426 0.013 ast.py:414(visit)
676 0.003 0.000 16.270 0.024 ast.py:1706(unparse)
676 0.002 0.000 16.266 0.024 ast.py:814(visit)
2523181/676 1.749 0.000 16.240 0.024 ast.py:804(traverse)
676 0.004 0.000 16.234 0.024 ast.py:828(visit_Module)
1352/676 0.002 0.000 16.230 0.024 ast.py:821(_write_docstring_and_traverse_body)
676 0.001 0.000 16.223 0.024 ast.py:1031(visit_FunctionDef)
676 0.006 0.000 16.221 0.024 ast.py:1037(_function_helper)
15259/2097 0.698 0.000 15.973 0.008 ast.py:1071(visit_If)
676 0.001 0.000 15.542 0.023 ast.py:197(fix_missing_locations)
3515543/676 6.715 0.000 15.541 0.023 ast.py:205(_fix)
3013/2944 0.003 0.000 15.503 0.005 ast.py:980(visit_Try)
3013/2944 0.012 0.000 15.500 0.005 ast.py:965(do_visit_try)
1 0.000 0.000 10.626 10.626 runners.py:141(_run_server_forever)
1 10.608 10.608 10.624 10.624 {method 'run_forever' of 'uvloop.loop.Loop' objects}
18846 10.117 0.001 10.117 0.001 {built-in method builtins.compile}
247070 1.170 0.000 9.178 0.000 ast.py:1436(visit_Compare)
7030410 4.501 0.000 7.975 0.000 ast.py:267(iter_child_nodes)
1229 0.003 0.000 7.778 0.006 ast.py:33(parse)
238365/237689 0.665 0.000 5.694 0.000 ast.py:1472(visit_Call)
237695 0.583 0.000 3.344 0.000 ast.py:869(visit_Assign)
299 0.005 0.000 2.863 0.010 __init__.py:1(<module>)
233327 0.424 0.000 2.630 0.000 ast.py:1314(visit_Set)
9421737 2.069 0.000 2.623 0.000 ast.py:255(iter_fields)
2545/605 0.010 0.000 2.033 0.003 <frozen importlib._bootstrap>:1167(_find_and_load)
2148/209 0.009 0.000 2.029 0.010 <frozen importlib._bootstrap>:1122(_find_and_load_unlocked)
2041/211 0.007 0.000 2.014 0.010 <frozen importlib._bootstrap>:666(_load_unlocked)
1895/211 0.004 0.000 2.008 0.010 <frozen importlib._bootstrap_external>:934(exec_module)
1896 0.025 0.000 2.004 0.001 router.py:147(add)
4665/422 0.002 0.000 1.993 0.005 <frozen importlib._bootstrap>:233(_call_with_frames_removed)
236127 0.181 0.000 1.865 0.000 route.py:277(finalize)
683 0.004 0.000 1.812 0.003 signals.py:214(add)
1 0.000 0.000 1.806 1.806 app.py:173(_get_app)
1 0.000 0.000 1.806 1.806 loader.py:55(load)
611/602 0.001 0.000 1.792 0.003 __init__.py:108(import_module)
613/602 0.001 0.000 1.791 0.003 <frozen importlib._bootstrap>:1194(_gcd_import)
236127 0.843 0.000 1.685 0.000 route.py:218(_finalize_params)
1520 0.169 0.000 1.680 0.001 group.py:110(merge)
14157267/14157252 1.662 0.000 1.675 0.000 {built-in method builtins.getattr}
2 0.000 0.000 1.631 0.816 app.py:81(create_app)
1 0.000 0.000 1.629 1.629 app.py:110(prepare_app)
17037150/17036768 1.572 0.000 1.577 0.000 {built-in method builtins.isinstance}
1 0.000 0.000 1.522 1.522 manager.py:151(load_components)
1 0.000 0.000 1.489 1.489 manager.py:315(_load_components)
94 0.001 0.000 1.487 0.016 manager.py:270(_load_component)
4020064 1.093 0.000 1.472 0.000 ast.py:729(write)
239830/236625 0.188 0.000 1.390 0.000 ast.py:696(interleave)
596 0.000 0.000 1.377 0.002 manager.py:196(load)
227675 0.330 0.000 1.326 0.000 route.py:126(__eq__)
505410 0.446 0.000 1.313 0.000 ast.py:1248(visit_Constant)
85 0.003 0.000 1.289 0.015 logic.py:1(<module>)
1 0.006 0.006 1.268 1.268 blueprint.py:117(build_spec)
753996 0.325 0.000 1.244 0.000 contextlib.py:132(__enter__)
739 0.001 0.000 1.213 0.002 types.py:66(__init__)
739 0.001 0.000 1.212 0.002 types.py:73(guard)
739 0.004 0.000 1.212 0.002 types.py:74(<dictcomp>)
2993 0.012 0.000 1.207 0.000 types.py:401(_properties)
328 0.000 0.000 1.196 0.004 builders.py:95(parameter)
328 0.001 0.000 1.195 0.004 definitions.py:247(make)
676 0.002 0.000 1.151 0.002 tree.py:477(render)
8949/676 0.025 0.000 1.149 0.002 tree.py:91(render)
8273 0.058 0.000 1.123 0.000 tree.py:109(to_src)
79 0.006 0.000 1.096 0.014 endpoints.py:1(<module>)
737/56 0.001 0.000 1.076 0.019 {built-in method builtins.__import__}