Worker process starts very slowly in new version, even leads to ACK timeout

[zhanghaofei]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

After updating to the latest version, the worker process takes an excessively long time to start up. This severe delay even causes the system to fail to receive an ACK (acknowledgement) within the expected timeframe, eventually resulting in a timeout termination.

Test Result:
Through further testing, I have identified a strong correlation between the startup delay and the number of routes in the application. The performance scales negatively with the number of routes; specifically, the more routes there are, the slower the worker process starts. This suggests a potential performance regression or inefficiency in the route registration/initialization process in the new version.

Root Cause:

After a thorough investigation, I pinpointed the performance bottleneck to the add_auto_handlers function in sanic-ext, with the add_options handler being the primary contributor to the delay. The issue is resolved immediately after disabling these auto handlers via configuration, confirming they are the root cause of the startup latency.

Code snippet

Incorrect Code (Causes Slow Startup):

from sanic import Sanic
from sanic.response import text


app = Sanic("MyHelloWorldApp")

async def hello_world(request):
    return text("Hello, world.")

# 
for i in range(200):
    app.add_route(hello_world, f"/test-{i}", name=f"test-{i}")

if __name__ == '__main__':
    app.run(host='0.0.0.0', port=8000, debug=True, workers=1, verbosity=2)

Output:

Main  23:14:48 DEBUG: 

                 Sanic
         Build Fast. Run Fast.


Main  23:14:48 INFO: Sanic v25.3.0
Main  23:14:48 INFO: Goin' Fast @ http://0.0.0.0:8000
Main  23:14:48 INFO: app: MyHelloWorldApp
Main  23:14:48 INFO: mode: debug, single worker
Main  23:14:48 INFO: server: sanic, HTTP/1.1
Main  23:14:48 INFO: python: 3.11.5
Main  23:14:48 INFO: platform: Windows-10-10.0.26100-SP0
Main  23:14:48 INFO: packages: sanic-routing==23.12.0, sanic-ext==24.12.0
Main  23:14:49 DEBUG: Creating multiprocessing context using 'spawn'
Main  23:14:49 DEBUG: Starting a process: Sanic-Server-0-0
Srv 0 23:14:49 DEBUG: Triggering server events: server.init.before
verbosity=1
Srv 0 23:14:49 DEBUG: Dispatching signal: server.init.before
verbosity=1
Executing <Task finished name='Task-2' coro=<Sanic._server_event() done, defined at D:\setup\miniconda3\envs\py311\Lib\site-packages\sanic\app.py:2425> result=None created at D:\setup\miniconda3\envs\py311\Lib\asyncio\tasks.py:670> took 5.360 seconds
Srv 0 23:14:54 DEBUG: Process ack: Sanic-Server-0-0 [8804]
Srv 0 23:14:54 DEBUG: Triggering server events: server.init.after
verbosity=1
Srv 0 23:14:54 DEBUG: Dispatching signal: server.init.after
verbosity=1
Srv 0 23:14:54 INFO: Starting worker [8804]

Correct Code (Fast Startup):

from sanic import Sanic
from sanic.response import text


app = Sanic("MyHelloWorldApp")
# fix
app.config["CORS_AUTOMATIC_OPTIONS"] = False
app.config["HTTP_AUTO_OPTIONS"] = False
app.config["HTTP_AUTO_HEAD"] = False
app.config["HTTP_AUTO_TRACE"] = False


async def hello_world(request):
    return text("Hello, world.")


for i in range(200):
    app.add_route(hello_world, f"/test-{i}", name=f"test-{i}")

if __name__ == '__main__':
    app.run(host='0.0.0.0', port=8000, debug=True, workers=1, verbosity=2)

Output:

Main  22:57:40 DEBUG: 

                 Sanic
         Build Fast. Run Fast.


Main  22:57:40 INFO: Sanic v25.3.0
Main  22:57:40 INFO: Goin' Fast @ http://0.0.0.0:8000
Main  22:57:40 INFO: app: MyHelloWorldApp
Main  22:57:40 INFO: mode: debug, single worker
Main  22:57:40 INFO: server: sanic, HTTP/1.1
Main  22:57:40 INFO: python: 3.11.5
Main  22:57:40 INFO: platform: Windows-10-10.0.26100-SP0
Main  22:57:40 INFO: packages: sanic-routing==23.12.0, sanic-ext==24.12.0
Main  22:57:40 DEBUG: Creating multiprocessing context using 'spawn'
Main  22:57:40 DEBUG: Starting a process: Sanic-Server-0-0
Srv 0 22:57:40 DEBUG: Triggering server events: server.init.before
verbosity=1
Srv 0 22:57:40 DEBUG: Dispatching signal: server.init.before
verbosity=1
Srv 0 22:57:40 DEBUG: Process ack: Sanic-Server-0-0 [10724]
Srv 0 22:57:40 DEBUG: Triggering server events: server.init.after
verbosity=1
Srv 0 22:57:40 DEBUG: Dispatching signal: server.init.after
verbosity=1
Srv 0 22:57:40 INFO: Starting worker [10724]

Expected Behavior

The worker process should start up promptly and send an ACK signal back to the main process or requester upon being ready.

How do you run Sanic?

As a script (app.run or Sanic.serve)

Operating System

Linux

Sanic Version

23.3.0 ~ 35.3.0

Additional context

No response