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.