Why not response returned immediately?

Questions and Help
#1

hello everyone,

I’m trying to test my project when 30 requests are sent at the same time.

My Questions are:

  1. When I run 30 requests at the same time, the responses do not return immediately, but collectively after a certain amount of time.
    I imagine the results will return at equal intervals.

  2. I meet the same problem here. Workers have uniformity requests.
    Since mentioned using multiprocessing spawn, I thought we had solved the problem with the latest version.

Appreciate any support.

My test code as the following:

sanic version: 22.9.1

app.py

from sanic import Sanic
from sanic.response import text
from sanic.log import logger
import random
import os


class MyConfig:
    ACCESS_LOG = True


app = Sanic("MyHelloWorldApp")
app.update_config(MyConfig)


def countdown(n=5000000):
    while n > 0:
        rn = random.randint(1, 10)
        n -= rn


@app.get("/")
async def hello_world(request):
    logger.info(f"pid: {os.getpid()}")
    countdown()
    return text("Hello, world.")

if __name__ == "__main__":
    app.run(port=5001, workers=2,)

send.py

from concurrent.futures import ThreadPoolExecutor
import requests
import datetime
import time


def send():
    now = datetime.datetime.now().strftime("%H:%M:%S")
    print(f"send {now}")
    ts = time.time()
    requests.get("http://localhost:5001/",
                 headers={'Cache-Control': 'no-cache'})
    te = time.time()
    print("Finish {:3f}".format(te - ts))
    # return r


def main():
    with ThreadPoolExecutor(max_workers=30) as executor:
        features = [executor.submit(send) for _ in range(30)]
        for _ in features:
            pass


if __name__ == "__main__":
    main()

Results when I run send.py

…
send 20:31:29
send 20:31:29
send 20:31:29
send 20:31:29
Finish 0.425397
Finish 0.440028
Finish 2.530030
Finish 2.539155
Finish 2.536322
Finish 2.540317
Finish 2.525164
Finish 9.979830
Finish 9.978587
Finish 9.973895
Finish 9.977069
Finish 9.976723
Finish 9.979774
Finish 9.980963
Finish 9.958031
Finish 9.962271
Finish 9.966130
Finish 9.982406
Finish 9.985687
Finish 9.982178
Finish 9.967140
Finish 9.954723
Finish 9.956860
Finish 9.981751
Finish 9.975298
Finish 9.977007
Finish 9.980968
Finish 9.983316
Finish 9.980071
Finish 9.961572

from sanic log I find different worker has unevent requests，like:

1 [543]
29 [545]

Thanks.

#2

What you are doing is not ideal for sure. It is a CPU bound operation in a request handler. What I suspect is happening is that your first worker is blocked up and so the OS is directing to the second worker.

If you change to an IO-bound operation, you will see that the results are much more as you might expect.

@app.get("/")
async def hello_world(request):
    logger.info(f"pid: {os.getpid()}")
    for _ in range(random.randint(1, 10)):
        await sleep(random.random())
    return text("Hello, world.")

image
image578×638 7.68 KB

image
image180×622 6.9 KB

#3

Thanks for your reply !

If I run same code with hypercorn, I can get the results are much more as I expected.

hypercorn server:app -b 127.0.0.1:5001 -w 2

sc2022-12-12 220600
sc2022-12-12 220600244×861 10.5 KB

My questions are:

  1. Why is there such a difference between Sanic and Sanic + ASGI?
  2. But why the responses do not return immediately even the operation in handler finished.
    From Sanic log, we can find that the operation in handler finished by a few second, but responses are not returned.
    sc2022-12-12 222000
    sc2022-12-12 2220002106×1316 144 KB
#4

Thanks. Will look into this when I have a moment.