python-socketio not handling events concurrently with gevent_uwsgi

[stoarca]

Minimal test case:
app.py

import gevent.monkey
gevent.monkey.patch_all()

import logging
import socketio
import time

from flask import Flask

sio = socketio.Server(logger=logging, engineio_logger=logging, async_mode='gevent_uwsgi')

class ChatNamespace(socketio.Namespace):
  def on_delayed_ping(self, sid, data):
    print('got socket ping %s' % data)
    time.sleep(1)
    print('returning socket pong %s' % data)
    self.emit('delayed_pong', data, room=sid)

chatNamespace = ChatNamespace('/chat')
sio.register_namespace(chatNamespace)

app = Flask(__name__)

@app.route('/delayed_ping')
def ping():
  print('got ping')
  time.sleep(1)
  print('returning pong')
  return 'pong'

app = socketio.Middleware(sio, app)

Start the server with uwsgi --http :5000 --gevent 1000 --http-websockets --master --wsgi-file app.py --callable app

Then, run test.js with node test.js

var rp = require('request-promise');
var io = require('socket.io-client');

socket = io.connect('http://localhost:5000/chat', {
  'reconnection delay': 0,
  'reopen delay': 0,
  'force new connection': true,
});

var httpCall = function(i) {
  rp.get('http://localhost:5000/delayed_ping').then(function(data) {
    console.log(i + ' ' + data);
  });
};

var socketCall = function(i) {
  socket.emit('delayed_ping', {i: i});
};
for (var i = 0; i < 100; ++i) {
  httpCall(i);
  socketCall(i);
}

The regular http requests are all run in parallel and take a total of approximately 1 second for all of them. The socket calls, on the other hand, are run one at a time (100 seconds total). It's quite possible I've misconfigured something, but my understanding is that all of the socket calls should run in parallel as well.

Note that if I run node test.js on two separate terminals, the server processes two requests at a time (i.e. it runs in parallel across multiple sockets). So it's just within a single socket that it does not parallelize.

[stoarca]

Update: I found async_handlers in the docs. Setting this to True (why is this not the default?) alleviates the problem somewhat, but not completely. Specifically, my output now looks like this:

got socket ping {u'i': 0}
returning socket pong {u'i': 0}
got socket ping {u'i': 1}
returning socket pong {u'i': 1}
got socket ping {u'i': 2}
returning socket pong {u'i': 2}
got socket ping {u'i': 3}
returning socket pong {u'i': 3}
got socket ping {u'i': 4}
returning socket pong {u'i': 4}
got socket ping {u'i': 5}
returning socket pong {u'i': 5}
got socket ping {u'i': 6}
returning socket pong {u'i': 6}
got socket ping {u'i': 7}
returning socket pong {u'i': 7}
got socket ping {u'i': 8}
returning socket pong {u'i': 8}
got socket ping {u'i': 9}
returning socket pong {u'i': 9}
got socket ping {u'i': 10}
returning socket pong {u'i': 10}
got socket ping {u'i': 11}
returning socket pong {u'i': 11}
got socket ping {u'i': 12}
returning socket pong {u'i': 12}
got socket ping {u'i': 13}
returning socket pong {u'i': 13}
got socket ping {u'i': 14}
returning socket pong {u'i': 14}
got socket ping {u'i': 15}
returning socket pong {u'i': 15}
got socket ping {u'i': 16}
returning socket pong {u'i': 16}
got socket ping {u'i': 17}
returning socket pong {u'i': 17}
got socket ping {u'i': 18}
returning socket pong {u'i': 18}
got socket ping {u'i': 19}
returning socket pong {u'i': 19}
got socket ping {u'i': 20}
returning socket pong {u'i': 20}
got socket ping {u'i': 21}
returning socket pong {u'i': 21}
got socket ping {u'i': 22}
returning socket pong {u'i': 22}
got socket ping {u'i': 23}
returning socket pong {u'i': 23}
got socket ping {u'i': 24}
got socket ping {u'i': 25}
got socket ping {u'i': 26}
got socket ping {u'i': 27}
got socket ping {u'i': 28}
got socket ping {u'i': 29}
got socket ping {u'i': 30}
got socket ping {u'i': 31}
got socket ping {u'i': 32}
got socket ping {u'i': 33}
got socket ping {u'i': 34}
got socket ping {u'i': 35}
got socket ping {u'i': 36}
got socket ping {u'i': 37}
got socket ping {u'i': 38}
got socket ping {u'i': 39}
got socket ping {u'i': 40}
got socket ping {u'i': 41}
got socket ping {u'i': 42}
got socket ping {u'i': 43}
got socket ping {u'i': 44}
got socket ping {u'i': 45}
got socket ping {u'i': 46}
got socket ping {u'i': 47}
got socket ping {u'i': 48}
got socket ping {u'i': 49}
got socket ping {u'i': 50}
got socket ping {u'i': 51}
got socket ping {u'i': 52}
got socket ping {u'i': 53}
got socket ping {u'i': 54}
got socket ping {u'i': 55}
got socket ping {u'i': 56}
got socket ping {u'i': 57}
got socket ping {u'i': 58}
got socket ping {u'i': 59}
got socket ping {u'i': 60}
got socket ping {u'i': 61}
got socket ping {u'i': 62}
got socket ping {u'i': 63}
got socket ping {u'i': 64}
got socket ping {u'i': 65}
got socket ping {u'i': 66}
got socket ping {u'i': 67}
got socket ping {u'i': 68}
got socket ping {u'i': 69}
got socket ping {u'i': 70}
got socket ping {u'i': 71}
got socket ping {u'i': 72}
got socket ping {u'i': 73}
got socket ping {u'i': 74}
got socket ping {u'i': 75}
got socket ping {u'i': 76}
got socket ping {u'i': 77}
got socket ping {u'i': 78}
got socket ping {u'i': 79}
got socket ping {u'i': 80}
got socket ping {u'i': 81}
got socket ping {u'i': 82}
got socket ping {u'i': 83}
got socket ping {u'i': 84}
got socket ping {u'i': 85}
got socket ping {u'i': 86}
got socket ping {u'i': 87}
got socket ping {u'i': 88}
got socket ping {u'i': 89}
got socket ping {u'i': 90}
got socket ping {u'i': 91}
got socket ping {u'i': 92}
got socket ping {u'i': 93}
got socket ping {u'i': 94}
got socket ping {u'i': 95}
got socket ping {u'i': 96}
got socket ping {u'i': 97}
got socket ping {u'i': 98}
got socket ping {u'i': 99}
returning socket pong {u'i': 24}
returning socket pong {u'i': 25}
returning socket pong {u'i': 26}
returning socket pong {u'i': 27}
returning socket pong {u'i': 28}
returning socket pong {u'i': 29}
returning socket pong {u'i': 30}
returning socket pong {u'i': 31}
returning socket pong {u'i': 32}
returning socket pong {u'i': 33}
returning socket pong {u'i': 34}
returning socket pong {u'i': 35}
returning socket pong {u'i': 36}
returning socket pong {u'i': 37}
returning socket pong {u'i': 38}
returning socket pong {u'i': 39}
returning socket pong {u'i': 40}
returning socket pong {u'i': 41}
returning socket pong {u'i': 42}
returning socket pong {u'i': 43}
returning socket pong {u'i': 44}
returning socket pong {u'i': 45}
returning socket pong {u'i': 46}
returning socket pong {u'i': 47}
returning socket pong {u'i': 48}
returning socket pong {u'i': 49}
returning socket pong {u'i': 50}
returning socket pong {u'i': 51}
returning socket pong {u'i': 52}
returning socket pong {u'i': 53}
returning socket pong {u'i': 54}
returning socket pong {u'i': 55}
returning socket pong {u'i': 56}
returning socket pong {u'i': 57}
returning socket pong {u'i': 58}
returning socket pong {u'i': 59}
returning socket pong {u'i': 60}
returning socket pong {u'i': 61}
returning socket pong {u'i': 62}
returning socket pong {u'i': 63}
returning socket pong {u'i': 64}
returning socket pong {u'i': 65}
returning socket pong {u'i': 66}
returning socket pong {u'i': 67}
returning socket pong {u'i': 68}
returning socket pong {u'i': 69}
returning socket pong {u'i': 70}
returning socket pong {u'i': 71}
returning socket pong {u'i': 72}
returning socket pong {u'i': 73}
returning socket pong {u'i': 74}
returning socket pong {u'i': 75}
returning socket pong {u'i': 76}
returning socket pong {u'i': 77}
returning socket pong {u'i': 78}
returning socket pong {u'i': 79}
returning socket pong {u'i': 80}
returning socket pong {u'i': 81}
returning socket pong {u'i': 82}
returning socket pong {u'i': 83}
returning socket pong {u'i': 84}
returning socket pong {u'i': 85}
returning socket pong {u'i': 86}
returning socket pong {u'i': 87}
returning socket pong {u'i': 88}
returning socket pong {u'i': 89}
returning socket pong {u'i': 90}
returning socket pong {u'i': 91}
returning socket pong {u'i': 92}
returning socket pong {u'i': 93}
returning socket pong {u'i': 94}
returning socket pong {u'i': 95}
returning socket pong {u'i': 96}
returning socket pong {u'i': 97}
returning socket pong {u'i': 98}
returning socket pong {u'i': 99}

The first 23 responses are slow, and the rest are fast. The 23 seems to be fixed for the size of the for loop in the test. Every time I run it with 100 or less, it's 23 slow, the rest fast. If I run it with 200, the first 100 or so go fast, then the rest go a bit slower. I'll start spelunking through the code, but my initial guess is there's some sort of queuing or buffering that's not working quite as expected.

[miguelgrinberg]

why is this not the default?

Because it can cause multiple event handlers for a given client to run in parallel. In same cases this is fine, but in some others it may not, and it may require the application to explicitly protect against race conditions due to the parallelism.

In general, it is not a great idea to have event handlers that are slow. It would be better to start a secondary background task that sleeps for one second and then emits than having that in the event handler function. If you code the sleep and the second emit in a background task, then you should not need to use the async_handlers option.

The significance of the number 23 escapes me though, I will play with your example to see if I can figure it out.

[ecamaj]

I'm using uwsgi, async_mode="gevent_uwsgi" and set async_handler=True, uwsgi.ini has gevent=1000.
This is how it is called in the code:

from django.core.wsgi import get_wsgi_application
import socketio
import os

from Messaging import Messaging

os.environ.setdefault("DJANGO_SETTINGS_MODULE", "djangoproject.settings")

application = get_wsgi_application()

# create a Socket.IO server
sio = socketio.Server(async_mode='gevent_uwsgi', async_handlers=True)
handler = Messaging('/socket')
handler.server = sio
sio.register_namespace(handler)

# wrap WSGI application with socketio's middleware
application = socketio.Middleware(sio, application)

uwsgi on start gives this:

- async cores set to 1000 - fd table size: 1048576
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address 127.0.0.1:8000 fd 3
Python version: 3.4.3 (default, Nov 17 2016, 01:12:14)  [GCC 4.8.4]
Python main interpreter initialized at 0x1224100
python threads support enabled
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 20732928 bytes (20247 KB) for 1000 cores
*** Operational MODE: async ***

but I cannot make it run background tasks in parallel.
I start background task in on_message and it always run them sequentially:

997000
998000
999000
Finished long
Start long ...
0
1000
2000
3000
4000

regardless if I call in the same on_message background task twice or I make two calls instantly on the client to call on_message.
Any ideas? This is very important for me.

[ecamaj]

Additional problem is that when called simultaneously from two different clients, on_message from second client is not executed until first is completely finished:

Before start long call - client 1 // this is in on_message
After start long call - client 1 // this is in on_message
Data received: {'data': 'some data 1'} // this is in on_message
Start long ... // this is in background task
Finished long // this is in background task
Before start long call - client 2 // this is in on_message
After start long call - client 2 // this is in on_message
Data received: {'data': 'some data 2'} // this is in on_message
Start long ... // this is in background task
Finished long // this is in background task

[miguelgrinberg]

Gevent uses cooperative multitasking. That means that your functions need to release the CPU voluntarily to let other tasks run. In your background task, you need to call sio.sleep(0) often (such as once per loop iteration) to release the CPU to other waiting tasks.

[ecamaj]

Yeah.. that could be a problem. What if I call another long-lasting function that I cannot influence? No help...?

[miguelgrinberg]

Well, an asynchronous application needs to be fully asynchronous. Even if you have one function that is blocking, that breaks the whole thing.

Gevent allows you to monkey patch the Python standard library and make many of its blocking functions non-blocking. This helps in many cases. If this external function that you are using does any networking or threading, the monkey patching will allow those to be done in a cooperative way. If this function is just using CPU, then I'm afraid it is a problem. You will need to move that function to another thread or process, so that it does not interfere with the asynchronous tasks. Maybe the gevent.threadpool module can help with that.

[ecamaj]

Seems that monkey patch did the trick. Thanks!

[miguelgrinberg]

This issue will be automatically closed due to being inactive for more than six months. Seeing that I haven't responded to your last comment, it is quite possible that I have dropped the ball on this issue and I apologize about that. If that is the case, do not take the closing of the issue personally as it is an automated process doing it, just reopen it and I'll get back to you.