Performance issue

[pistol-whip]

I am experiencing a massive delay in establishing a connection and then frequent stalling.

The setup:

• 10 Instances of the server app, only serving websockets using Flask SocketIO
• 3 nginx proxy servers with sticky sessions for all ws traffic
• 1 redis instance (exclusive for pubsub)

The app uses gevent in combination with geventwebsocket. Monkey patching is correctly applied.

Connected are around 500 users total, messages are coming in at around 5k/s (redis ops). CPU/memory etc. are not a problem and available plentiful.

The behaviour is that it takes around 9 seconds for the initial SocketIO packet to arrive at the client and then it basically stalls out, closes the connection and repeats the cycle with an ever increasing connection "delay". What I have noticed is that it seems to collect a couple hundred messages before sending anything out to the client. This shows also in the memory usage.

The server app basically only relays messages sent via external clients, so I am at a loss why this is happening. I have tried horizontally scaling the app, but that seems to make the issue worse.

core.py

import ...

redis_connection: str = 'redis://{}:{}'.format(
	redis_settings['host'], 
	redis_settings['port']
)

# FlaskEx only overrides process_response in order to change some response headers
app 		= FlaskEx(
	Environment.APP_NAME,
	static_url_path = '/assets',
	static_folder	= 'etc/assets'
)

verbosity = ('--debug' in sys.argv and Environment.DEVELOPMENT)
	
socketio	= SocketIO(
	app, 
	async_mode		= 'gevent', 
	manage_session	= False,
	message_queue	= redis_connection,
	cors_allowed_origins = '*',
	logger			= verbosity,
	engineio_logger = verbosity,
	path			= 'connect',
	always_connect = True
)

socketio.py

import ...

@socketio.on('keepalive')
def command_keepalive():
	emit('keepalive')

@socketio.on('connect')
def event_connect():
	emit('ack', {
	        'shard': Environment.SHARD_UUID
        })

# I have stripped out some auth logic which is non essential to the issue
@socketio.on('join')
def command_join(payload: dict):
	join_room(room = payload['r'], sid = request.sid)

@socketio.on('leave')
def command_leave(payload: dict):
	leave_room(room = payload['r'], sid = request.sid)

run.py

import gevent.monkey
gevent.monkey.patch_all()

if __name__ == '__main__':
	import geventwebsocket
        import ...
        from core import app
	app.socketio.run(
			demeter.app.app,
			host		= Environment.HOST,
			port		= Environment.PORT
        )

py-spy dump

Total Samples 5100
GIL: 97.00%, Active: 100.00%, Threads: 11

  %Own   %Total  OwnTime  TotalTime  Function (filename:line)
  2.00%   2.00%    1.88s     1.88s   url_quote (werkzeug/urls.py:572)
  1.00%   1.00%    1.71s     1.71s   recv (gevent/_socketcommon.py:657)
  4.00%   4.00%    1.59s     1.59s   _cookie_quote (werkzeug/_internal.py:412)
  3.00%   3.00%    1.31s     1.31s   dump_payload (itsdangerous/url_safe.py:44)
  0.00%   0.00%   0.840s    0.840s   bind_to_environ (werkzeug/routing.py:1689)
  4.00%   7.00%   0.740s     1.16s   top (werkzeug/local.py:247)
  4.00%   4.00%   0.660s    0.660s   _cookie_parse_impl (werkzeug/_internal.py:465)
  3.00%   3.00%   0.590s    0.590s   _cookie_quote (werkzeug/_internal.py:413)
  1.00%   1.00%   0.580s    0.580s   _cookie_quote (werkzeug/_internal.py:416)
  3.00%   3.00%   0.530s    0.530s   iterencode (json/encoder.py:257)
  1.00%   1.00%   0.510s    0.510s   derive_key (itsdangerous/signer.py:130)
  2.00%   2.00%   0.470s    0.470s   _dt_as_utc (werkzeug/_internal.py:320)
  0.00%   0.00%   0.470s    0.490s   run (gevent/hub.py:647)
  1.00%   1.00%   0.450s    0.450s   recv (gevent/_socketcommon.py:663)
  0.00%   0.00%   0.430s    0.430s   load_payload (itsdangerous/url_safe.py:33)
  1.00%   1.00%   0.420s    0.420s   acquire (gevent/thread.py:121)
  0.00%  14.00%   0.420s     8.27s   emit (flask_socketio/__init__.py:825)
  1.00%  12.00%   0.380s     7.22s   _publish (socketio/redis_manager.py:80)
  0.00%   0.00%   0.370s    0.370s   format_datetime (email/utils.py:162)
  1.00%   1.00%   0.360s    0.520s   max_cookie_size (flask/wrappers.py:164)
  2.00%   2.00%   0.320s    0.320s   __getattr__ (werkzeug/local.py:151)
  0.00%   7.00%   0.320s     1.80s   dumps (itsdangerous/_json.py:18)

[miguelgrinberg]

The most important piece of information is missing: Socket.IO server logs. See the troubleshooting section of the documentation if you don't know how to turn logging on.

[pistol-whip]

Sorry, apparently my upload failed for some reason.

Thats about 4 minutes of runtime:
debug.log

[miguelgrinberg]

The clients have to follow the protocol and always respond to pings in a timely manner. Why are your clients misbehaving? That's the problem here.

[pistol-whip]

The issue is not with the clients. I have set up a second deployment with the same exact setup, the sole difference being that only a handfull of clients connect to it. No issues whatsoever. Looking at the live deployment with 500+ concurrent connections, its stalling and resulting in a high CPU every couple of connects.

[miguelgrinberg]

Okay, so let me explain how this works.

The server sends ping packets every 25 seconds. It expects the client to respond with a pong packet with in 5 seconds. If the server does not see a pong packet in that time, then it will consider the client gone and stop talking to it. If in spite of not sending pongs, the client decides to hold on to the socket and not close it, then that connection will remain open until the client closes it, but it is not going to be used anymore.

There are two possible reasons why the server did not see a pong packet:

• the client didn't send it
• the client sent it, but the server was too busy doing other things and couldn't process it in time

I have no way to know which of the two situations you're in, but you seem to think it is the second one. So why is the server too busy? Are you doing heavy CPU work? That is incompatible with an asynchronous server and it can definitely lead to missed packets and delays.

[pistol-whip]

The client most definitly sends it and there is basically no CPU work going on. The app only has a join and leave operation. WS is only used to transmit data to the clients without any interaction.

[miguelgrinberg]

@pistol-whip you have to recognize that this problem is caused, either directly or indirectly by something your own application is doing. You are basically deflecting all the opportunities I'm giving you to think about how your application works with a "no, it's not that", while at the same time provide no additional information or proof that there is a bug in this package.

In my view, you already decided that this is a bug your application has nothing to do with, and somehow expect that I will come up with a solution for you. But I have no knowledge of how you use the server, and what your clients do, so how can I?

If you want to build a small server and a small client that I can use to test this problem here I can debug it. Other than that, I'm not sure what else I can offer with the little information that I have.