More time spent on FlowDataControlQueue

[prav2019]

It looks like the async websocket server we are using spending more time in FlowDataControlQueue, what does that indicate? I could reduce it by adding await asyncio.sleep(0) in websocket handlers, but not sure how many I should add ? doesn't make sense in adding everywhere. Could anyone help me on what might be happening ? Also using web.run to start the app

[prav2019]

Looks like the aiohttp websocket app degrade over time dropping/ delaying the tasks created from create_task api and eventually need to restart the service once every 2-3 hrs

[Dreamsorcerer]

Not sure that has any relation to the graphs shown. What does the code look like? Again, more information is needed if you want help.

[prav2019]

I cannot add complete code here, but I will add prototype probably:

`async for msg in websocket_response:

creating bg tasks (using asyncio create_task)

await asyncio.sleep(0)
`

[Dreamsorcerer]

It's the bit in the middle I'm most interested in. You may not be using create_task() correctly. If you want to spin up tasks in the background without waiting on them, then you probably want to use aiojobs instead.

[prav2019]

The callgraph to trace the path

[Dreamsorcerer]

You're going to have to provide some more information on what I'm looking at and what you expect to be happening...

If that graph is showing amount of time the program is at a particular point in the code, then that looks pretty normal. I'm pretty sure the FlowControlDataQueue is where the socket code is handled, so whenever you are waiting on socket data it would be sitting in the code. It is not blocking or causing any performance issues, you application is simply idling at this point.

[prav2019]

flowcontroldataqueue read api

[prav2019]

the problem gets worse as we get more traffic

[prav2019]

We are uploading profile dumps to gcs every 15 min, i see sometimes there is a delay, few seconds delay are fine, but there seems to be a too much delay. So something is not right with tasks

[prav2019]

MONITOR: current tasks: 324 (tasks created using create_bg_task the function that's mentioned above) ttlcache size: 290 redis_conn: connections: 8 subs: 12370 max_rss: 81.48MB now_rss: 81.48MB loc_peers (ws conn in the pod): 161

[prav2019]

def create_bg_task(coro):
task = loop.create_task(coro)
create_bg_task.refs.add(task) # create a strong ref
# To prevent keeping references to finished tasks forever,
# make each task remove its own reference from the set after
# completion:
task.add_done_callback(handle_task_result)
return task
FYI again...

[prav2019]

task_starving_test_code.zip
Here is the test code that i have created to simulate the issue we are having

1. When 200 ws connections are created, the save profiler file task never executes and there will be lot of request handlers tasks in pending state:
   
   2> The profiler file save task executes after closing client (within few seconds)
   3> Adding await asyncio.sleep(0) fixes this problem
   
   (top one with sleeps and bottom one without sleeps)
   So are sleeps necessary here when lot of time is spent in request handlers to explicitly give control to execute other tasks.

Since i can reproduce with the code, want to understand what exactly is helping the tasks execution with sleep(s) inside websocket reads (for loop)

[Dreamsorcerer]

Still rather difficult to figure anything out given the random snippets of information. At a guess, there are 2 things I can think of.

First, in the case of your sleep() call, this is causing an explicit yield to the event loop and allowing it to run some other code. Maybe the code where you are sleeping is actually taking a fair amount of time and stopping other tasks from running without the sleep(). I'm not familiar with how your tool measures time spent in async functions, so it may also mean that these calls have been started and then get blocked by the busy function before they resume.

Second, create_by_task() is a difficult thing to get right, so I strongly suggest replacing this with aiojobs (there will probably be a new class in asyncio in the next 2 Python releases which can replace it later).

If you want any more help than that, you'll need to create a minimal reproducer that we can run and try out.

[prav2019]

#7344 I created issue and i have added a sample code where i can replicate the behavior

[prav2019]

Looks like more than create task it is linked to the ws reads and await ws.send calls they are noy yielding sometimes, worse during high load. I have explained in the issue with more details , expected behavior and zip file that has code to run and test

[prav2019]

task_starving_test_code.zip
FYI here is the minimal reproducer code. I have posted logs , expected behavior here:
#7344

[prav2019]

@Dreamsorcerer Thank you so much, hope this helps to go through what's happening.

[bdraco]

Please give 3.10.2 a try. It should scale a bit better. There is still more to do.

[tarasko]

I ended up making and using my own small WebSockets library.
https://github.com/tarasko/picows
Check out the benchmark I made, still a lot of room for improvement in aiohttp.