paster breaks by more than 5 requests/sec

[davidak]

my setup:

virtual machine with 2 cores and 4 gb ram
debian 7
postgresql
paster
nginx
mediagoblin 0.6.2.dev
​init script from joar

i want to test the performance of paster and evaluate other application-servers like gunicorn.

5 requests/sec works fine, but with 6 something breaks.

i get a "504 Gateway Time-out" from nginx, meaning the backend is not there.

also stopping of paster don't work:

root@mediagoblin:~# /etc/init.d/mediagoblin-paster stop
Stopping GNU MediaGoblin paster fcgi server: mediagoblin-paster failed!

if i kill the processes and restart it, it works again.

error from the paster log:

Error - <class 'sqlalchemy.exc.DatabaseError'>: (DatabaseError) error with no message from the libpq None None
URL: http://mediagoblin.lan/u/davidak/m/dsc-0046/
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/Paste-1.7.5.1-py2.7.egg/paste/exceptions/errormiddleware.py', line 144 in __call__
  app_iter = self.application(environ, sr_checker)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/Paste-1.7.5.1-py2.7.egg/paste/urlmap.py', line 203 in __call__
  return app(environ, start_response)
File '/var/www/mediagoblin/mediagoblin/app.py', line 267 in __call__
  self.db.reset_after_request()
File '/var/www/mediagoblin/mediagoblin/db/open.py', line 48 in reset_after_request
  Session.rollback()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/scoping.py', line 149 in do
  return getattr(self.registry(), name)(*args, **kwargs)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/session.py', line 685 in rollback
  self.transaction.rollback()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/session.py', line 380 in rollback
  transaction._rollback_impl()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/session.py', line 408 in _rollback_impl
  t[1].rollback()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 1184 in rollback
  self._do_rollback()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 1222 in _do_rollback
  self.connection._rollback_impl()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 477 in _rollback_impl
  self._handle_dbapi_exception(e, None, None, None, None)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 1024 in _handle_dbapi_exception
  exc_info
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/util/compat.py', line 196 in raise_from_cause
  reraise(type(exception), exception, tb=exc_tb)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 474 in _rollback_impl
  self.engine.dialect.do_rollback(self.connection)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/default.py', line 294 in do_rollback
  dbapi_connection.rollback()
DatabaseError: (DatabaseError) error with no message from the libpq None None


CGI Variables
-------------
  DOCUMENT_ROOT: '/etc/nginx/html'
  DOCUMENT_URI: '/u/davidak/m/dsc-0046/'
  GATEWAY_INTERFACE: 'CGI/1.1'
  HTTP_ACCEPT: 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8'
  HTTP_ACCEPT_ENCODING: 'gzip,deflate,sdch'
  HTTP_ACCEPT_LANGUAGE: 'de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4'
  HTTP_CACHE_CONTROL: 'max-age=0'
  HTTP_CONNECTION: 'keep-alive'
  HTTP_COOKIE: 'mediagoblin_csrftoken=1413966666120940524; mediagoblin_csrftoken=1413966666120940524; MGSession=eyJtZXNzYWdlcyI6W10sInVzZXJfaWQiOiIyIn0.Bj3ypQ.sqgR5cZlSfbRjiDb5df1RNU5020; mediagoblin_csrftoken=1413966666120940524'
  HTTP_DNT: '1'
  HTTP_HOST: 'mediagoblin.lan'
  HTTP_REFERER: 'http://mediagoblin.lan/'
  HTTP_USER_AGENT: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.116 Safari/537.36'
  PATH_INFO: '/u/davidak/m/dsc-0046/'
  REDIRECT_STATUS: '200'
  REMOTE_ADDR: '10.0.0.8'
  REMOTE_PORT: '55655'
  REQUEST_METHOD: 'GET'
  REQUEST_URI: '/u/davidak/m/dsc-0046/'
  SCRIPT_FILENAME: '/etc/nginx/html/u/davidak/m/dsc-0046/'
  SERVER_ADDR: '10.0.0.11'
  SERVER_NAME: 'mediagoblin.lan'
  SERVER_PORT: '80'
  SERVER_PROTOCOL: 'HTTP/1.1'
  SERVER_SOFTWARE: 'nginx/1.2.1'


WSGI Variables
--------------
  application: {(None, '/mgoblin_static'): <StaticURLParser '/var/www/mediagoblin/mediagoblin/static'>, (None, '/mgoblin_media'): <StaticURLParser '/var/www/mediagoblin/user_dev/media/public'>, (None, ''): <mediagoblin.app.MediaGoblinApp object at 0x1cb1750>, (None, '/plugin_static'): <StaticURLParser '/var/www/mediagoblin/user_dev/plugin_static'>, (None, '/theme_static'): <StaticURLParser '/var/www/mediagoblin/user_dev/theme_static'>}
  paste.throw_errors: True
  werkzeug.request: <Request 'http://mediagoblin.lan/u/davidak/m/dsc-0046/' [GET]>
  wsgi process: 'Multiprocess'
------------------------------------------------------------
Error - <class 'sqlalchemy.exc.DatabaseError'>: (DatabaseError) error with no message from the libpq 'SELECT core__users.id AS core__users_id, core__users.username AS core__users_username, core__users.email AS core__users_email, core__users.pw_hash AS core__users_pw_hash, core__users.created AS core__users_created, core__users.wants_comment_notification AS core__users_wants_comment_notification, core__users.wants_notifications AS core__users_wants_notifications, core__users.license_preference AS core__users_license_preference, core__users.url AS core__users_url, core__users.bio AS core__users_bio, core__users.uploaded AS core__users_uploaded, core__users.upload_limit AS core__users_upload_limit \nFROM core__users \nWHERE core__users.id = %(param_1)s' {'param_1': u'2'}
URL: http://mediagoblin.lan/u/davidak/m/dsc-0046/
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/Paste-1.7.5.1-py2.7.egg/paste/exceptions/errormiddleware.py', line 144 in __call__
  app_iter = self.application(environ, sr_checker)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/Paste-1.7.5.1-py2.7.egg/paste/urlmap.py', line 203 in __call__
  return app(environ, start_response)
File '/var/www/mediagoblin/mediagoblin/app.py', line 263 in __call__
  return self.call_backend(environ, start_response)
File '/var/www/mediagoblin/mediagoblin/app.py', line 205 in call_backend
  mg_request.setup_user_in_request(request)
File '/var/www/mediagoblin/mediagoblin/tools/request.py', line 38 in setup_user_in_request
  request.user = User.query.get(request.session['user_id'])
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py', line 827 in get
  return loading.load_on_ident(self, key)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/loading.py', line 226 in load_on_ident
  return q.one()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py', line 2323 in one
  ret = list(self)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py', line 2366 in __iter__
  return self._execute_and_instances(context)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py', line 2381 in _execute_and_instances
  result = conn.execute(querycontext.statement, self._params)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 662 in execute
  params)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 761 in _execute_clauseelement
  compiled_sql, distilled_params
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 874 in _execute_context
  context)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 1024 in _handle_dbapi_exception
  exc_info
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/util/compat.py', line 196 in raise_from_cause
  reraise(type(exception), exception, tb=exc_tb)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py', line 867 in _execute_context
  context)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/default.py', line 324 in do_execute
  cursor.execute(statement, parameters)
DatabaseError: (DatabaseError) error with no message from the libpq 'SELECT core__users.id AS core__users_id, core__users.username AS core__users_username, core__users.email AS core__users_email, core__users.pw_hash AS core__users_pw_hash, core__users.created AS core__users_created, core__users.wants_comment_notification AS core__users_wants_comment_notification, core__users.wants_notifications AS core__users_wants_notifications, core__users.license_preference AS core__users_license_preference, core__users.url AS core__users_url, core__users.bio AS core__users_bio, core__users.uploaded AS core__users_uploaded, core__users.upload_limit AS core__users_upload_limit \nFROM core__users \nWHERE core__users.id = %(param_1)s' {'param_1': u'2'}


CGI Variables
-------------
  DOCUMENT_ROOT: '/etc/nginx/html'
  DOCUMENT_URI: '/u/davidak/m/dsc-0046/'
  GATEWAY_INTERFACE: 'CGI/1.1'
  HTTP_ACCEPT: 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8'
  HTTP_ACCEPT_ENCODING: 'gzip,deflate,sdch'
  HTTP_ACCEPT_LANGUAGE: 'de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4'
  HTTP_CACHE_CONTROL: 'max-age=0'
  HTTP_CONNECTION: 'keep-alive'
  HTTP_COOKIE: 'mediagoblin_csrftoken=1413966666120940524; mediagoblin_csrftoken=1413966666120940524; MGSession=eyJtZXNzYWdlcyI6W10sInVzZXJfaWQiOiIyIn0.Bj3ypQ.sqgR5cZlSfbRjiDb5df1RNU5020; mediagoblin_csrftoken=1413966666120940524'
  HTTP_DNT: '1'
  HTTP_HOST: 'mediagoblin.lan'
  HTTP_USER_AGENT: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.116 Safari/537.36'
  PATH_INFO: '/u/davidak/m/dsc-0046/'
  REDIRECT_STATUS: '200'
  REMOTE_ADDR: '10.0.0.8'
  REMOTE_PORT: '55705'
  REQUEST_METHOD: 'GET'
  REQUEST_URI: '/u/davidak/m/dsc-0046/'
  SCRIPT_FILENAME: '/etc/nginx/html/u/davidak/m/dsc-0046/'
  SERVER_ADDR: '10.0.0.11'
  SERVER_NAME: 'mediagoblin.lan'
  SERVER_PORT: '80'
  SERVER_PROTOCOL: 'HTTP/1.1'
  SERVER_SOFTWARE: 'nginx/1.2.1'


WSGI Variables
--------------
  application: {(None, '/mgoblin_static'): <StaticURLParser '/var/www/mediagoblin/mediagoblin/static'>, (None, '/mgoblin_media'): <StaticURLParser '/var/www/mediagoblin/user_dev/media/public'>, (None, ''): <mediagoblin.app.MediaGoblinApp object at 0x1cb1750>, (None, '/plugin_static'): <StaticURLParser '/var/www/mediagoblin/user_dev/plugin_static'>, (None, '/theme_static'): <StaticURLParser '/var/www/mediagoblin/user_dev/theme_static'>}
  paste.throw_errors: True
  werkzeug.request: <Request 'http://mediagoblin.lan/u/davidak/m/dsc-0046/' [GET]>
  wsgi process: 'Multiprocess'
------------------------------------------------------------

2014-04-27 06:29:41,495 WARNING [mediagoblin.tools.request] Killing session for user id u'2'
Error - <class 'sqlalchemy.exc.NoSuchColumnError'>: "Could not locate column in row for column 'core__user_bans.user_id'"
URL: http://mediagoblin.lan/u/davidak/m/dsc-0046/
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/Paste-1.7.5.1-py2.7.egg/paste/exceptions/errormiddleware.py', line 144 in __call__
  app_iter = self.application(environ, sr_checker)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/Paste-1.7.5.1-py2.7.egg/paste/urlmap.py', line 203 in __call__
  return app(environ, start_response)
File '/var/www/mediagoblin/mediagoblin/app.py', line 263 in __call__
  return self.call_backend(environ, start_response)
File '/var/www/mediagoblin/mediagoblin/app.py', line 240 in call_backend
  response = controller(request)
File '/var/www/mediagoblin/mediagoblin/decorators.py', line 43 in wrapper
  if request.user.is_banned():
File '/var/www/mediagoblin/mediagoblin/db/models.py', line 136 in is_banned
  return UserBan.query.get(self.id) is not None
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py', line 827 in get
  return loading.load_on_ident(self, key)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/loading.py', line 226 in load_on_ident
  return q.one()
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py', line 2323 in one
  ret = list(self)
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/loading.py', line 72 in instances
  rows = [process[0](row, None) for row in fetch]
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/orm/loading.py', line 356 in _instance
  tuple([row[column] for column in pk_cols])
File '/var/www/mediagoblin/local/lib/python2.7/site-packages/SQLAlchemy-0.8.6-py2.7-linux-x86_64.egg/sqlalchemy/engine/result.py', line 314 in _key_fallback
  expression._string_or_unprintable(key))
NoSuchColumnError: "Could not locate column in row for column 'core__user_bans.user_id'"


CGI Variables
-------------
  CSRF_TOKEN: u'1413966666120940524'
  DOCUMENT_ROOT: '/etc/nginx/html'
  DOCUMENT_URI: '/u/davidak/m/dsc-0046/'
  GATEWAY_INTERFACE: 'CGI/1.1'
  HTTP_ACCEPT: 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8'
  HTTP_ACCEPT_ENCODING: 'gzip,deflate,sdch'
  HTTP_ACCEPT_LANGUAGE: 'de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4'
  HTTP_CACHE_CONTROL: 'max-age=0'
  HTTP_CONNECTION: 'keep-alive'
  HTTP_COOKIE: 'mediagoblin_csrftoken=1413966666120940524; mediagoblin_csrftoken=1413966666120940524; MGSession=eyJtZXNzYWdlcyI6W10sInVzZXJfaWQiOiIyIn0.Bj3ypQ.sqgR5cZlSfbRjiDb5df1RNU5020; arp_scroll_position=191; mediagoblin_csrftoken=1413966666120940524'
  HTTP_DNT: '1'
  HTTP_HOST: 'mediagoblin.lan'
  HTTP_REFERER: 'http://mediagoblin.lan/'
  HTTP_USER_AGENT: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.116 Safari/537.36'
  PATH_INFO: '/u/davidak/m/dsc-0046/'
  REDIRECT_STATUS: '200'
  REMOTE_ADDR: '10.0.0.8'
  REMOTE_PORT: '56201'
  REQUEST_METHOD: 'GET'
  REQUEST_URI: '/u/davidak/m/dsc-0046/'
  SCRIPT_FILENAME: '/etc/nginx/html/u/davidak/m/dsc-0046/'
  SERVER_ADDR: '10.0.0.11'
  SERVER_NAME: 'mediagoblin.lan'
  SERVER_PORT: '80'
  SERVER_PROTOCOL: 'HTTP/1.1'
  SERVER_SOFTWARE: 'nginx/1.2.1'


WSGI Variables
--------------
  application: {(None, '/mgoblin_static'): <StaticURLParser '/var/www/mediagoblin/mediagoblin/static'>, (None, '/mgoblin_media'): <StaticURLParser '/var/www/mediagoblin/user_dev/media/public'>, (None, ''): <mediagoblin.app.MediaGoblinApp object at 0x2efe750>, (None, '/plugin_static'): <StaticURLParser '/var/www/mediagoblin/user_dev/plugin_static'>, (None, '/theme_static'): <StaticURLParser '/var/www/mediagoblin/user_dev/theme_static'>}
  paste.throw_errors: True
  werkzeug.request: <Request 'http://mediagoblin.lan/u/davidak/m/dsc-0046/' [GET]>
  wsgi process: 'Multiprocess'
------------------------------------------------------------

[Christopher Allan Webber]

Hm. I'm not sure why this would be since it looks like you're using the multiprocess approach above, not multithreaded stuff (which actually very well might break). It looks like it's an SQLAlchemy-connected-to-the-db error. But why? I'm not sure... I think this will take more digging.

[Ben Sturmfels]

Hi David,

Thanks very much for taking the time to raise this issue. I've just attempted a similar test on a less powerful machine running Nginx, Postgresql and Debian 8.5 using ApacheBench (ab). I was able run 100 successful successful requests with 10 concurrent connections:

ab -n 100 -c 10 https://mymediagoblinsite/u/ben/m/myitem/

Give this successful test and that we're now three major versions on, I'd suggest that we close this issue for now. If David or anyone else is able to replicate this issue on version 0.9.0 (reported for 0.6.2.dev), please reopen the ticket.

Cheers,
Ben