Why do UVICORN/Starlette/FastAPI spawn more threads when not using "ASYNC" and don't when using "ASYNC"?

Question

Okay, so I was working on a comparison study on using ASYNC vs without using ASYNC in FastAPI. However, I have arrived at some unexpected results, and don't understand why.

Here is the setup 1:

THE API WHICH DOES NOT USE ASYNC

import uvicorn
from fastapi import FastAPI
import PIL.Image as Image
import requests
from loguru import logger
import sys

log_format = "{level} {process}-{thread} {time} {name}:{line} - {message}"
logger.remove()
logger.add(sys.stderr, format=log_format, backtrace=True, diagnose=True)
logger.add("logs/" + "t_{time}.log", format=log_format, colorize=True, backtrace=True, diagnose=True)

Image.MAX_IMAGE_PIXELS = None

def get_the_image_from_net():
    a = requests.get("https://eoimages.gsfc.nasa.gov/images/imagerecords/73000/73751/world.topo.bathy.200407.3x21600x21600.A1.jpg")
    return True


app = FastAPI()

@app.get("/expectoPatronum")
def get_image_of_the_new_world():
    """
    Gets Image of the World
    """
    logger.info("Received request for getting Image of the world")
    image_bytes: bytes = get_the_image_from_net()
    logger.info("Image has been downloaded and processed as bytes array")
    return True

uvicorn.run(app, host="0.0.0.0", port=10009)

How I am calling ABOVE API (by using Multiprocessing Pool)

import time
from multiprocessing import Pool, Manager
import requests


def test_function(index_iterator: int):
    start_time = time.time()
    response = requests.get("http://localhost:10009/expectoPatronum")
    print(f"response.content: {str(response.content)}")
    if response.status_code != 200:
        print("----------------------NOT 200")
        print(f"response.content: {str(response.content)}")
    end_time = time.time()
    elapsed_time = end_time - start_time


pool = Pool(5)
pool.map(test_function, [i for i in range(1,6)])
pool.close

and this is what the LOGS read from my API's end when they are called:

INFO 9408-140671786272512 2022-07-13T01:32:37.498465+0530 __main__:27 - Received request for getting Image of the world
INFO 9408-140671777879808 2022-07-13T01:32:37.501623+0530 __main__:27 - Received request for getting Image of the world
INFO 9408-140671769487104 2022-07-13T01:32:37.504744+0530 __main__:27 - Received request for getting Image of the world
INFO 9408-140671760897792 2022-07-13T01:32:37.504929+0530 __main__:27 - Received request for getting Image of the world
INFO 9408-140671752242944 2022-07-13T01:32:37.505638+0530 __main__:27 - Received request for getting Image of the world
INFO 9408-140671786272512 2022-07-13T01:33:04.845982+0530 __main__:29 - Image has been downloaded and processed as bytes array
INFO 9408-140671777879808 2022-07-13T01:33:16.167435+0530 __main__:29 - Image has been downloaded and processed as bytes array
INFO 9408-140671769487104 2022-07-13T01:33:17.284000+0530 __main__:29 - Image has been downloaded and processed as bytes array
INFO 9408-140671752242944 2022-07-13T01:33:37.771086+0530 __main__:29 - Image has been downloaded and processed as bytes array
INFO 9408-140671760897792 2022-07-13T01:33:38.016435+0530 __main__:29 - Image has been downloaded and processed as bytes array

Please note: there are multiple threads created (140671786272512, 140671777879808 ..and so on)

Here is the setup 2:

THE API WHICH USES ASYNC

import uvicorn
from fastapi import FastAPI, Response, APIRouter
import httpx
from loguru import logger
import sys

log_format = "{level} {process}-{thread} {time} {name}:{line} - {message}"
logger.remove()
logger.add(sys.stderr, format=log_format, backtrace=True, diagnose=True)
logger.add("logs/" + "t_{time}.log", format=log_format, colorize=True, backtrace=True, diagnose=True)

Image.MAX_IMAGE_PIXELS = None

async def get_the_image_from_net():
    async with httpx.AsyncClient() as client:
        a = await client.get('https://eoimages.gsfc.nasa.gov/images/imagerecords/73000/73751/world.topo.bathy.200407.3x21600x21600.A1.jpg')

    return True


app = FastAPI()

@app.get("/expectoPatronum")
async def get_image_of_the_new_world():
    """
    Gets Image of the World
    """
    logger.info("Received request for getting Image of the world")
    image_bytes = await get_the_image_from_net()
    logger.info("Image has been downloaded and processed as bytes array")
    return True

uvicorn.run(app, host="0.0.0.0", port=10008)

How I am calling ABOVE API (by using Multiprocessing Pool (same as above calling method, different PORT number though)

import time
from multiprocessing import Pool, Manager
import requests


def test_function(index_iterator: int):
    start_time = time.time()
    response = requests.get("http://localhost:10008/expectoPatronum")
    print(f"response.content: {str(response.content)}")
    if response.status_code != 200:
        print("----------------------NOT 200")
        print(f"response.content: {str(response.content)}")
    end_time = time.time()
    elapsed_time = end_time - start_time


pool = Pool(5)
pool.map(test_function, [i for i in range(1,6)])
pool.close

and this is what the LOGS read from my API's end when they are called:

INFO 9442-140295303571264 2022-07-13T01:36:26.762525+0530 __main__:43 - Received request for getting Image of the world
INFO 9442-140295303571264 2022-07-13T01:36:26.776561+0530 __main__:43 - Received request for getting Image of the world
INFO 9442-140295303571264 2022-07-13T01:36:26.783669+0530 __main__:43 - Received request for getting Image of the world
INFO 9442-140295303571264 2022-07-13T01:36:26.790367+0530 __main__:43 - Received request for getting Image of the world
INFO 9442-140295303571264 2022-07-13T01:36:26.796934+0530 __main__:43 - Received request for getting Image of the world
INFO 9442-140295303571264 2022-07-13T01:37:38.086156+0530 __main__:45 - Image has been downloaded and processed as bytes array
INFO 9442-140295303571264 2022-07-13T01:37:43.709798+0530 __main__:45 - Image has been downloaded and processed as bytes array
INFO 9442-140295303571264 2022-07-13T01:37:43.827959+0530 __main__:45 - Image has been downloaded and processed as bytes array
INFO 9442-140295303571264 2022-07-13T01:37:47.218717+0530 __main__:45 - Image has been downloaded and processed as bytes array
INFO 9442-140295303571264 2022-07-13T01:37:51.712889+0530 __main__:45 - Image has been downloaded and processed as bytes array

Please note: there is only 1 thread (140295303571264)

Now I am unable to figure out: Why in SETUP-1, uvicorn spawns more than 1 thread? I thought it is a single-threaded Server and how can I restrict it to spawn only 1 thread inside the process?

The time-results from both setups are really discouraging. For SETUP-1 which does not use async, times are: 27.36284899711609,38.68544268608093,39.79848337173462,60.28416633605957,60.529775857925415

For SETUP-2 which uses async, times are: 71.32960891723633,76.95274710655212,77.07157778739929,80.4650149345398,84.95978450775146

FastAPI uses a threadpool of 40 threads internally to handle requests using non-async endpoints. When using async, only a single thread is used (since a thread not awaiting should be occupied with CPU bound stuff). You can usually tell your ASGI server to run multiple workers instead. — MatsLindh, Jul 12 '22 at 20:56
Yup, "adding" `async` to my non-async API made it single-threaded like I wanted it to be. — raghavsikaria, Jul 13 '22 at 14:36

score 1 · Answer 1 · answered Feb 16 '23 at 11:03

1

When you declare a path operation function with normal def instead of async def, it is run in an external threadpool that is then awaited, instead of being called directly (as it would block the server). You can read more in FastAPI documentation

answered Feb 16 '23 at 11:03

Jean Eric TUYISHIMIRE

21
3