Python 3.5 aiohttp blocks even when using async/aw

Question

I'm running a test aiohttp webserver:

#!/usr/bin/env python3

from aiohttp import web
import time
import asyncio
import random
import string
import logging

logger = logging.getLogger('webserver')
logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

def randomword(length):
    return ''.join(random.choice(string.ascii_lowercase) for i in range(length))

async def hello(request):
    sleeptime = 10 # seconds

    requestid = randomword(5)
    logger.info("Request id: {} received - will sleep for {}".format(requestid, sleeptime))

    await asyncio.sleep(sleeptime)

    logger.info("Request id: {} wakeup and respond".format(requestid))
    return web.json_response()

# create app and register with request handler
app = web.Application()
app.router.add_get('/', hello)
web.run_app(app, port='15000')

This is expected to be able to handle multiple incoming request at the same time without having to wait for one request to complete before processing the next one. However, it is not doing so - the processing is sequential (note the start time of 2nd/3rd request is after the previous requests completion):

======== Running on http://0.0.0.0:15000/ ========
(Press CTRL+C to quit)
2016-10-23 02:28:23,911 - webserver - INFO - Request id: hpzdo received - will sleep for 10
2016-10-23 02:28:33,922 - webserver - INFO - Request id: hpzdo wakeup and respond
2016-10-23 02:28:33,947 - webserver - INFO - Request id: pdfbs received - will sleep for 10
2016-10-23 02:28:43,957 - webserver - INFO - Request id: pdfbs wakeup and respond
2016-10-23 02:28:43,971 - webserver - INFO - Request id: dmkav received - will sleep for 10
2016-10-23 02:28:53,982 - webserver - INFO - Request id: dmkav wakeup and respond

I would expect the start time for each request be almost same (depending on how fast I'm submitting them; here I'm submitting manually within a second or two).

Answer 1

Something is wrong with your testing technique.

Running wrk tool against your server provides different result.

Command to run:

wrk http://127.0.0.1:15000/  

Server output:

======== Running on http://0.0.0.0:15000 ========
(Press CTRL+C to quit)
2016-10-23 14:58:56,447 - webserver - INFO - Request id: hkkrp received - will sleep for 10
2016-10-23 14:58:56,447 - webserver - INFO - Request id: cysoy received - will sleep for 10
2016-10-23 14:58:56,448 - webserver - INFO - Request id: udwxe received - will sleep for 10
2016-10-23 14:58:56,448 - webserver - INFO - Request id: moqkf received - will sleep for 10
2016-10-23 14:58:56,449 - webserver - INFO - Request id: shetp received - will sleep for 10
2016-10-23 14:58:56,450 - webserver - INFO - Request id: fhilc received - will sleep for 10
2016-10-23 14:58:56,451 - webserver - INFO - Request id: birax received - will sleep for 10
2016-10-23 14:58:56,452 - webserver - INFO - Request id: yyeoc received - will sleep for 10
2016-10-23 14:58:56,453 - webserver - INFO - Request id: mpkwf received - will sleep for 10
2016-10-23 14:58:56,454 - webserver - INFO - Request id: nkxiz received - will sleep for 10
2016-10-23 14:59:06,450 - webserver - INFO - Request id: hkkrp wakeup and respond
2016-10-23 14:59:06,451 - webserver - INFO - Request id: cysoy wakeup and respond
2016-10-23 14:59:06,451 - webserver - INFO - Request id: udwxe wakeup and respond
2016-10-23 14:59:06,452 - webserver - INFO - Request id: moqkf wakeup and respond
2016-10-23 14:59:06,452 - webserver - INFO - Request id: shetp wakeup and respond
2016-10-23 14:59:06,453 - webserver - INFO - Request id: fmpmm received - will sleep for 10
2016-10-23 14:59:06,453 - webserver - INFO - Request id: uusnt received - will sleep for 10
2016-10-23 14:59:06,453 - webserver - INFO - Request id: kjlzk received - will sleep for 10
2016-10-23 14:59:06,453 - webserver - INFO - Request id: elhje received - will sleep for 10
2016-10-23 14:59:06,453 - webserver - INFO - Request id: bkvjp received - will sleep for 10
2016-10-23 14:59:06,454 - webserver - INFO - Request id: fhilc wakeup and respond
2016-10-23 14:59:06,454 - webserver - INFO - Request id: birax wakeup and respond
2016-10-23 14:59:06,454 - webserver - INFO - Request id: yyeoc wakeup and respond
2016-10-23 14:59:06,455 - webserver - INFO - Request id: nyhba received - will sleep for 10
2016-10-23 14:59:06,455 - webserver - INFO - Request id: iqjvr received - will sleep for 10
2016-10-23 14:59:06,455 - webserver - INFO - Request id: osfsg received - will sleep for 10
2016-10-23 14:59:06,455 - webserver - INFO - Request id: mpkwf wakeup and respond
2016-10-23 14:59:06,456 - webserver - INFO - Request id: nkxiz wakeup and respond
2016-10-23 14:59:06,456 - webserver - INFO - Request id: ebzai received - will sleep for 10
2016-10-23 14:59:06,456 - webserver - INFO - Request id: erfhe received - will sleep for 10