878021 - Gevent blocking due to sqlalchemy statement compilation

Status: RESOLVED WONTFIX

(Cloud Services Graveyard :: Server: Sync, defect, P4)

Description

[Ryan Kelly [:rfkelly]]

Running the gevent-blocking-detector in prod produced several tracebacks such as the following:

[2013/May/30:18:45:11 -0700] Greenlet appears to be blocked
  File "/usr/lib64/python2.6/site-packages/gevent/greenlet.py", line 390, in run
    result = self._run(*self.args, **self.kwargs)
  File "/usr/lib/python2.6/site-packages/gunicorn/workers/ggevent.py", line 50, in handle
    self.handle_func(sock, addr)
  File "/usr/lib/python2.6/site-packages/gunicorn/workers/async.py", line 37, in handle
    self.handle_request(req, client, addr)
  File "/usr/lib/python2.6/site-packages/gunicorn/workers/ggevent.py", line 96, in handle_request
    super(GeventWorker, self).handle_request(*args)
  File "/usr/lib/python2.6/site-packages/gunicorn/workers/async.py", line 63, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/lib/python2.6/site-packages/services/util.py", line 304, in __call__
    return self.app(environ, start_response)
  File "/usr/lib/python2.6/site-packages/paste/translogger.py", line 68, in __call__
    return self.application(environ, replacement_start_response)
  File "/usr/lib/python2.6/site-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.6/site-packages/webob/dec.py", line 208, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.6/site-packages/services/baseapp.py", line 225, in __notified
    response = func(self, request)
  File "/usr/lib/python2.6/site-packages/services/baseapp.py", line 259, in __call__
    response = self._dispatch_request(request)
  File "/usr/lib/python2.6/site-packages/services/baseapp.py", line 317, in _dispatch_request
    response = self._dispatch_request_with_match(request, match)
  File "/usr/lib/python2.6/site-packages/services/baseapp.py", line 345, in _dispatch_request_with_match
    result = function(request, **params)
  File "/usr/lib/python2.6/site-packages/metlog/decorators/base.py", line 154, in __call__
    return self._real_call(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/services/metrics.py", line 101, in metlog_call
    return self._fn(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/metlog/decorators/base.py", line 154, in __call__
    return self._real_call(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/metlog/decorators/stats.py", line 50, in metlog_call
    result = self._fn(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/metlog/decorators/base.py", line 154, in __call__
    return self._real_call(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/services/metrics.py", line 114, in metlog_call
    result = self._fn(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/syncstorage/controller.py", line 407, in set_collection
    wbos, storage_time=storage_time)
  File "/usr/lib/python2.6/site-packages/syncstorage/storage/memcachedsql.py", line 245, in set_items
    storage_time=storage_time)
  File "/usr/lib/python2.6/site-packages/syncstorage/storage/sql.py", line 903, in set_items
    return self._do_query(sqltext(query), **values)
  File "/usr/lib64/python2.6/site-packages/sqlalchemy/sql/expression.py", line 1148, in text
    return _TextClause(text, bind=bind, *args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/sqlalchemy/sql/expression.py", line 2925, in __init__
    self.text = self._bind_params_regex.sub(repl, text)
  File "/usr/lib64/python2.6/site-packages/sqlalchemy/sql/expression.py", line 2919, in repl
    self.bindparams[m.group(1)] = bindparam(m.group(1))


This appears to be sqlalchemy taking its sweet time to compile a very large SQL statement, probably the multi-item INSERT ON DUPLICATE KEY UPDATE that we use for writing POST batches.

There's no indication of how long this blocks for.  The blocking-detector by default triggers at 0.1 seconds.  Bob, it would be interesting to re-enable this with the environment variable GEVENT_MAX_BLOCKING_TIME set to different values e.g. 0.2, 0.5, 1, etc to find out how long this is actually blocking for.

In any case, we should see if we can disable this compilation step to avoid holding up the event loop.

Comment 1

[Ryan Kelly [:rfkelly]]

(In reply to Ryan Kelly [:rfkelly] from comment #0)
> This appears to be sqlalchemy taking its sweet time to compile a very large
> SQL statement, probably the multi-item INSERT ON DUPLICATE KEY UPDATE that
> we use for writing POST batches.

Specifically, I think it's formatting the named query parameters into the positional style expected by mysql.  Since this is mysql-specific code anyway, we should do something a little more raw that doesn't require all the indirection.

Comment 2

[Ryan Kelly [:rfkelly]]

Bob, I'm going to close this out, but please do re-open or file a fresh bug with fresh tracebacks if it's still an issue in production.