Fastapi: [QUESTION] Would expect this simple example to behave asynchronously but it doesn't

Created on 15 Oct 2019  Â·  6Comments  Â·  Source: tiangolo/fastapi

Description

I'm probably not understanding the asynchronous concept correctly in FastAPI.

I'm accessing the root endpoint of the following app from two clients at the same time. I'd expect FastAPI to print Started twice:

from fastapi import FastAPI
import asyncio

app = FastAPI()

@app.get("/")
async def read_root():
    print('Started')
    await asyncio.sleep(5)
    print('Finished')
    return {"Hello": "World"}

Instead I get the following, which looks very much non asynchronous:

Started
Finished
INFO: ('127.0.0.1', 49655) - "GET / HTTP/1.1" 200
Started
Finished
INFO: ('127.0.0.1', 49655) - "GET / HTTP/1.1" 200

What am I missing?

question
Source
picture fhennecker

Most helpful comment

sorry misread you explain what you want and you're right it should do that

I guess when you state that you used 2 clients at the same time, maybe that was not enough at the same time, no idea how you proceeded to launch concurrent requests

See this log launching 10 concurrent requests with

ab -n 10 -c 10 http://localhost:8000/

/home/lotsos/.local/share/virtualenvs/rapidfastapitest-s8GpZJ_e/bin/python /home/lotsos/PycharmProjects/rapidfastapitest/625_asyn_question.py
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
INFO: Started server process [7007]
INFO: Waiting for application startup.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
2019-10-15 11:02:49,713 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,713 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47518) - "GET / HTTP/1.0" 200
2019-10-15 11:02:54,718 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,719 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,719 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,720 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,720 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,720 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,721 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,721 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,721 625_asyn_question DEBUG    Started
2019-10-15 11:02:59,719 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47520) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,720 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47522) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,720 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47524) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,721 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47526) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,721 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47528) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,722 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47530) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,722 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47532) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,723 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47534) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,724 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47536) - "GET / HTTP/1.0" 200

snippet used

import uvicorn
from fastapi import FastAPI
import asyncio

import logging

logger: logging.Logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

if not logger.hasHandlers():
    sh = logging.StreamHandler()
    fmt = logging.Formatter(fmt="%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
    sh.setFormatter(fmt)
    logger.addHandler(sh)
    logger.propagate = False



app = FastAPI()


@app.get("/")
async def read_root():
    logger.debug('Started')
    await asyncio.sleep(5)
    logger.debug('Finished')
    return {"Hello": "World"}



if __name__ == '__main__':
    uvicorn.run("625_asyn_question:app")
picture euri10 on 15 Oct 2019
👍2

All 6 comments

? I dont ge the point, what would you expect ?

On Tue, Oct 15, 2019 at 10:51 AM Florentin Hennecker <
[email protected]> wrote:

Description

I'm probably not understanding the asynchronous concept correctly in
FastAPI.

I'm accessing the root endpoint of the following app from two clients at
the same time. I'd expect FastAPI to print Started twice:

from fastapi import FastAPI
import asyncio

app = FastAPI()

@app.get("/")
async def read_root():
print('Started')
await asyncio.sleep(5)
print('Finished')
return {"Hello": "World"}

Instead I get the following, which looks very much non asynchronous:

Started
Finished
INFO: ('127.0.0.1', 49655) - "GET / HTTP/1.1" 200
Started
Finished
INFO: ('127.0.0.1', 49655) - "GET / HTTP/1.1" 200

What am I missing?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/tiangolo/fastapi/issues/625?email_source=notifications&email_token=AAINSPR56S4TKLAJY7RIGE3QOWAAFA5CNFSM4JAZKQPKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4HRZXPXA,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAINSPS4XCZNZDXET3RWU4LQOWAAFANCNFSM4JAZKQPA
.

--
benoit barthelet
http://pgp.mit.edu/pks/lookup?op=get&search=0xF150E01A72F6D2EE

euri10 picture euri10 on 15 Oct 2019

sorry misread you explain what you want and you're right it should do that

I guess when you state that you used 2 clients at the same time, maybe that was not enough at the same time, no idea how you proceeded to launch concurrent requests

See this log launching 10 concurrent requests with

ab -n 10 -c 10 http://localhost:8000/

/home/lotsos/.local/share/virtualenvs/rapidfastapitest-s8GpZJ_e/bin/python /home/lotsos/PycharmProjects/rapidfastapitest/625_asyn_question.py
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
INFO: Started server process [7007]
INFO: Waiting for application startup.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
2019-10-15 11:02:49,713 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,713 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47518) - "GET / HTTP/1.0" 200
2019-10-15 11:02:54,718 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,719 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,719 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,720 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,720 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,720 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,721 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,721 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,721 625_asyn_question DEBUG    Started
2019-10-15 11:02:59,719 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47520) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,720 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47522) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,720 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47524) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,721 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47526) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,721 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47528) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,722 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47530) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,722 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47532) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,723 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47534) - "GET / HTTP/1.0" 200
2019-10-15 11:02:59,724 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47536) - "GET / HTTP/1.0" 200

snippet used

import uvicorn
from fastapi import FastAPI
import asyncio

import logging

logger: logging.Logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

if not logger.hasHandlers():
    sh = logging.StreamHandler()
    fmt = logging.Formatter(fmt="%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
    sh.setFormatter(fmt)
    logger.addHandler(sh)
    logger.propagate = False



app = FastAPI()


@app.get("/")
async def read_root():
    logger.debug('Started')
    await asyncio.sleep(5)
    logger.debug('Finished')
    return {"Hello": "World"}



if __name__ == '__main__':
    uvicorn.run("625_asyn_question:app")
euri10 picture euri10 on 15 Oct 2019
👍2

Thanks for the quick reply!

You're right, with my snippet and your ab command I get a similar log to yours, and in fact I can see in both logs that the first request gets handled synchronously (both me and you get something like this):

2019-10-15 11:02:49,713 625_asyn_question DEBUG    Started
2019-10-15 11:02:54,713 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 47518) - "GET / HTTP/1.0" 200
... then a bunch of "Started"

Why is the first request handled like this?

fhennecker picture fhennecker on 15 Oct 2019

probably ab making a 1st request before the others ? read their doc maybe you'll find the answer :dancer:
using wrk you dont get that

(rapidfastapitest) ➜  rapidfastapitest git:(master) ✗ docker run --rm --network=host williamyeh/wrk -c 10 http://localhost:8000/

Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     0.00us    0.00us   0.00us    -nan%
    Req/Sec     0.00      0.00     0.00    100.00%
  20 requests in 10.02s, 2.77KB read
  Socket errors: connect 0, read 0, write 0, timeout 20
Requests/sec:      2.00
Transfer/sec:     283.30B

/home/lotsos/.local/share/virtualenvs/rapidfastapitest-s8GpZJ_e/bin/python /home/lotsos/PycharmProjects/rapidfastapitest/625_asyn_question.py
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
INFO: Started server process [16990]
INFO: Waiting for application startup.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
2019-10-15 12:10:30,190 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,190 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,190 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:30,191 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,191 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51420) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,192 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51422) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,192 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51424) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,193 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51428) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,193 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51426) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,194 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51430) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,194 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51432) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,195 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51434) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,195 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51436) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,196 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,196 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51438) - "GET / HTTP/1.1" 200
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,197 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,198 625_asyn_question DEBUG    Started
2019-10-15 12:10:35,198 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,197 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51436) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,197 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51428) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,198 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51422) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,199 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51424) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,199 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51432) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,200 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51420) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,200 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51426) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,201 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51434) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,201 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51430) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,202 625_asyn_question DEBUG    Finished
INFO: ('127.0.0.1', 51438) - "GET / HTTP/1.1" 200
2019-10-15 12:10:40,204 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,204 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,205 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,205 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,205 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,206 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,206 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,207 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,207 625_asyn_question DEBUG    Started
2019-10-15 12:10:40,207 625_asyn_question DEBUG    Started
2019-10-15 12:10:45,204 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,205 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,205 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,206 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,206 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,206 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,207 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,207 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,207 625_asyn_question DEBUG    Finished
2019-10-15 12:10:45,207 625_asyn_question DEBUG    Finished
euri10 picture euri10 on 15 Oct 2019

Hm well it's definitely not something to do with FastAPI then. Thanks a lot for the insight and the tests you ran!

fhennecker picture fhennecker on 15 Oct 2019
🚀1

Thanks for the help here @euri10 ! :clap: :bow:

Thanks for reporting back and closing the issue @fhennecker :+1:

tiangolo picture tiangolo on 10 Apr 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

cjw296 picture cjw296  Â·  3Comments
KoduIsGreat picture KoduIsGreat  Â·  3Comments
tsdmrfth picture tsdmrfth  Â·  3Comments
scheung38 picture scheung38  Â·  3Comments
vnwarrior picture vnwarrior  Â·  3Comments