Where is it stuck with 300 seconds

[rickcoup]

Long story short

I have two simple services running on local. (code is below). Why the response coming back in a very long time when I send 100 requests at the same time.

Expected behaviour

The response comes back in 5 seconds as set.

Actual behaviour

0 : A
1 : A
2 : A
3 : A
4 : A
5 : A
6 : A
7 : A
8 : A
9 : A
10 : A
11 : A
12 : A
13 : A
14 : A
15 : A
16 : A
17 : A
18 : A
19 : A
20 : A
21 : A
22 : A
23 : A
24 : A
25 : A
26 : A
27 : A
28 : A
29 : A
30 : A
31 : A
32 : A
33 : A
34 : A
35 : A
36 : A
37 : A
38 : A
39 : A
40 : A
41 : A
42 : A
43 : A
44 : A
45 : A
46 : A
47 : A
48 : A
49 : A
50 : A
51 : A
52 : A
53 : A
54 : A
55 : A
56 : A
57 : A
58 : A
59 : A
60 : A
61 : A
62 : A
63 : A
64 : A
65 : A
66 : A
67 : A
68 : A
69 : A
70 : A
71 : A
72 : A
73 : A
74 : A
75 : A
76 : A
77 : A
78 : A
79 : A
80 : A
81 : A
82 : A
83 : A
84 : A
85 : A
86 : A
87 : A
88 : A
89 : A
90 : A
91 : A
92 : A
93 : A
94 : A
95 : A
96 : A
97 : A
98 : A
99 : A
0 None
0 : B
300.51525688171387
1 None
1 : B
300.49500584602356
2 None
2 : B
300.4555251598358
3 None
3 : B
300.3783128261566
4 None
4 : B
300.22071409225464
5 None
5 : B
300.23106479644775
6 None
6 : B
300.392315864563
7 None
7 : B
300.24440002441406
8 None
8 : B
300.25392723083496
9 None
9 : B
300.4756729602814
10 None
10 : B
300.4071559906006
11 None
11 : B
300.2713232040405
12 None
12 : B
300.27943873405457
13 None
13 : B
300.422789812088
14 None
14 : B
300.2958700656891
15 None
15 : B
300.0411877632141
16 None
16 : B
300.3084819316864
17 None
17 : B
300.05593705177307
18 None
18 : B
300.06631875038147
19 None
19 : B
300.53166794776917
20 None
20 : B
300.5024359226227
21 None
21 : B
300.44071197509766
22 None
22 : B
300.3276689052582
23 None
23 : B
300.08137583732605
24 None
24 : B
300.0930027961731
25 None
25 : B
300.34224486351013
26 None
26 : B
300.10612392425537
27 None
27 : B
300.11883020401
28 None
28 : B
300.4653172492981
29 None
29 : B
300.356486082077
30 None
30 : B
300.1298317909241
31 None
31 : B
300.14036202430725
32 None
32 : B
300.3721601963043
33 None
33 : B
300.1537368297577
34 None
34 : B
300.16757106781006
35 None
35 : B
300.5329496860504
36 None
36 : B
300.486093044281
37 None
37 : B
300.3868417739868
38 None
38 : B
300.18363213539124
39 None
39 : B
300.1890799999237
40 None
40 : B
300.40212988853455
41 None
41 : B
300.2136299610138
42 None
42 : B
300.2241539955139
43 None
43 : B
300.5054609775543
44 None
44 : B
300.41709899902344
45 None
45 : B
300.23673129081726
46 None
46 : B
300.24992990493774
47 None
47 : B
300.43183994293213
48 None
48 : B
300.26059913635254
49 None
49 : B
300.27237820625305
50 None
50 : B
300.8833019733429
51 None
51 : B
300.51010394096375
52 None
52 : B
300.5330138206482
53 None
53 : B
300.5741229057312
54 None
54 : B
300.6693181991577
55 None
55 : B
300.9122197628021
56 None
56 : B
300.9347438812256
57 None
57 : B
300.5549099445343
58 None
58 : B
300.95762515068054
59 None
59 : B
300.9785771369934
60 None
60 : B
300.59788179397583
61 None
61 : B
300.6189019680023
62 None
62 : B
301.0007178783417
63 None
63 : B
301.02261090278625
64 None
64 : B
300.64508605003357
65 None
65 : B
300.6349558830261
66 None
66 : B
300.65782594680786
67 None
67 : B
300.67855286598206
68 None
68 : B
300.6703190803528
69 None
69 : B
300.7216079235077
70 None
70 : B
300.74448323249817
71 None
71 : B
300.78622698783875
72 None
72 : B
300.86886405944824
73 None
73 : B
301.0258448123932
74 None
74 : B
300.7404930591583
75 None
75 : B
300.75992798805237
76 None
76 : B
300.78198504447937
77 None
77 : B
300.77275586128235
78 None
78 : B
300.80641198158264
79 None
79 : B
300.82753825187683
80 None
80 : B
300.8673462867737
81 None
81 : B
300.819452047348
82 None
82 : B
300.8407459259033
83 None
83 : B
300.8630599975586
84 None
84 : B
300.8553509712219
85 None
85 : B
300.8940372467041
86 None
86 : B
300.9198160171509
87 None
87 : B
300.5764129161835
88 None
88 : B
300.64886569976807
89 None
89 : B
300.9098927974701
90 None
90 : B
300.9300842285156
91 None
91 : B
300.9527750015259
92 None
92 : B
300.74457120895386
93 None
93 : B
300.9750168323517
94 None
94 : B
300.99647426605225
95 None
95 : B
301.03903102874756
96 None
96 : B
300.62722301483154
97 None
97 : B
300.6200029850006
98 None
98 : B
300.74402117729187
99 None
99 : B
301.0251898765564

Steps to reproduce

Service #1, by calling http://localhost:8080

import os
os.environ['PYTHONASYNCIODEBUG'] = '1'
import json

from aiohttp import web
import aiohttp
import asyncio
import importlib
import time

#tasks = []
n = 0
m = 0

def mcowA(m):
   print (m, " : A") 
   return

async def fetch(session, url):
    try:
        async with session.get(url) as response:
        #async with getattr(session,"get")(url,proxy=proxy) as response:
            return await response.text()
    except Exception:
        import traceback
        traceback.format_exc()

def mcowB(n):
   print (n, " : B") 
   return

async def runMcows(request):
    start = time.time()
    global n,m
    mcowA(m)
    m=m+1
    async with aiohttp.ClientSession() as session:
        html = await fetch(session, 'http://localhost:8081')
        #html = await fetch(session, 'http://www.cpan.org/SITES.htm
    print(n,html)
    mcowB(n)
    end = time.time()
    print ( end - start)
    n=n+1

    return web.Response(text=html)

async def init():
    app = web.Application()
    app.add_routes([web.get('/', runMcows)])
    return await loop.create_server(
        app.make_handler(), '127.0.0.1', 8080)

loop = asyncio.get_event_loop()
loop.run_until_complete(init())
loop.run_forever()`

Service 2

from aiohttp import web
import asyncio
import time

async def hello(request):
    time.sleep(5)
    #await asyncio.sleep(5)
    return web.Response(text='dummy done5')

app = web.Application()
app.add_routes([web.get('/', hello)])

web.run_app(app,host='127.0.0.1', port=8081)

I understand the time.sleep(5) is blocking, but why it's blocking 300 seconds?
If changed to await asyncio.sleep(5), it works.

Your environment

mac os, python 3.6

[aio-libs-bot]

GitMate.io thinks the contributor most likely able to help you is @asvetlov.

[greshilov]

time.sleep will basically transform your asynchronous server to single-threaded synchronous server. So requests will be processed one by one, that's why the delay is so huge.

@asvetlov let's close this issue, it's definitely not a bug!

[Dreamsorcerer]

As mentioned, time.sleep() blocks the entire application, not just the current request. The next request is not getting processed until it reaches an await or returns from the handler.