RelStorage perfmetrics -> 504 Gateway Timeout

[Tres Seaver]

After pulling a fresh copy of the production database to
'karlstaging', I'm seeing Gateway timeouts which may be related
to how RelStorage is using perfmetrics::

  2013-03-27 12:28:32,608 - Thread -1256756416: Started on 1364401546.1; Running for 166.5 secs; request: GET https://karlstaging.gocept.com/communities/karl-developer-team/view.html
  Traceback:
    File "/srv/karlstaging/staging/29/eggs/slowlog-0.9-py2.6.egg/slowlog/tween.py", line 70, in __call__
      return self.handler(request)
    File "/srv/karlstaging/staging/29/eggs/pyramid-1.2.1-py2.6.egg/pyramid/tweens.py", line 17, in excview_tween
      response = handler(request)
    File "/srv/karlstaging/staging/29/eggs/pyramid_tm-0.5-py2.6.egg/pyramid_tm/__init__.py", line 100, in tm_tween
      response = handler(request)
    File "/srv/karlstaging/staging/29/eggs/pyramid-1.2.1-py2.6.egg/pyramid/router.py", line 153, in handle_request
      response = view_callable(context, request)
    File "/srv/karlstaging/staging/29/eggs/pyramid-1.2.1-py2.6.egg/pyramid/config/views.py", line 186, in _secured_view
      return view(context, request)
    File "/srv/karlstaging/staging/29/eggs/pyramid-1.2.1-py2.6.egg/pyramid/config/views.py", line 292, in rendered_view
      result = view(context, request)
    File "/srv/karlstaging/staging/29/src/karl/karl/views/community.py", line 136, in show_community_view
      recent_items_batch = get_recent_items_batch(context, request)
    File "/srv/karlstaging/staging/29/src/karl/karl/views/community.py", line 81, in get_recent_items_batch
      allowed={'query': effective_principals(request), 'operator': 'or'},
    File "/srv/karlstaging/staging/29/src/karl/karl/views/batch.py", line 144, in get_catalog_batch_grid
      batch = get_catalog_batch(context, request, **kw)
    File "/srv/karlstaging/staging/29/src/karl/karl/views/batch.py", line 51, in get_catalog_batch
      total, docids, resolver = searcher(**kw)
    File "/srv/karlstaging/staging/29/src/karl/karl/models/adapters.py", line 77, in __call__
      num, docids = self.catalog.search(**kw)
    File "/srv/karlstaging/staging/29/eggs/perfmetrics-1.0-py2.6.egg/perfmetrics/__init__.py", line 138, in call_with_metric
      return f(*args, **kw)
    File "/srv/karlstaging/staging/29/src/karl/karl/models/catalog.py", line 99, in search
      num, docids = self._search(*arg, **kw)
    File "/srv/karlstaging/staging/29/eggs/perfmetrics-1.0-py2.6.egg/perfmetrics/__init__.py", line 138, in call_with_metric
      return f(*args, **kw)
    File "/srv/karlstaging/staging/29/src/karl/karl/models/catalog.py", line 120, in _search
      res = super(CachingCatalog, self).search(*arg, **kw)
    File "/srv/karlstaging/staging/29/eggs/repoze.catalog-0.7.3-py2.6.egg/repoze/catalog/catalog.py", line 84, in search
      r = index.apply(index_query)
    File "/srv/karlstaging/staging/29/eggs/repoze.catalog-0.7.3-py2.6.egg/repoze/catalog/indexes/path2.py", line 357, in apply
      return self.search(path, depth, include_path, attr_checker)
    File "/srv/karlstaging/staging/29/eggs/repoze.catalog-0.7.3-py2.6.egg/repoze/catalog/indexes/path2.py", line 218, in search
      return self._simple_search(path, depth, include_path)
    File "/srv/karlstaging/staging/29/eggs/repoze.catalog-0.7.3-py2.6.egg/repoze/catalog/indexes/path2.py", line 247, in _simple_search
      theset = self.adjacency[docid]
    File "/srv/karlstaging/staging/29/eggs/ZODB3-3.10.5_perfmetrics-py2.6-linux-i686.egg/ZODB/Connection.py", line 860, in setstate
      self._setstate(obj)
    File "/srv/karlstaging/staging/29/eggs/ZODB3-3.10.5_perfmetrics-py2.6-linux-i686.egg/ZODB/Connection.py", line 901, in _setstate
      p, serial = self._storage.load(obj._p_oid, '')
    File "/srv/karlstaging/staging/29/eggs/perfmetrics-1.0-py2.6.egg/perfmetrics/__init__.py", line 114, in call_with_metric
      return f(*args, **kw)
    File "/srv/karlstaging/staging/29/eggs/RelStorage-1.5.1_perfmetrics2-py2.6.egg/relstorage/storage.py", line 460, in load
      state, tid_int = cache.load(cursor, oid_int)
    File "/srv/karlstaging/staging/29/eggs/RelStorage-1.5.1_perfmetrics2-py2.6.egg/relstorage/cache.py", line 279, in load
      state, tid_int = self.adapter.mover.load_current(cursor, oid_int)
    File "/srv/karlstaging/staging/29/eggs/perfmetrics-1.0-py2.6.egg/perfmetrics/__init__.py", line 114, in call_with_metric
      return f(*args, **kw)
    File "/srv/karlstaging/staging/29/eggs/RelStorage-1.5.1_perfmetrics2-py2.6.egg/relstorage/adapters/mover.py", line 104, in postgresql_load_current
      cursor.execute(stmt, (oid,))

It looks as though there are changes on the 'RelStorage' trunk
which mitigate this issue via sampling:

  https://github.com/zodb/relstorage/commit/d720f779dc02aef074b90f54e3d92088817aa899

I'm going to ask Shane if he can make a new release for us to
test on 'karlstaging'.

[Paul Everitt (paul-agendaless)]

Replaced by a ticket that is a little more accurate.

[Chris Rossi (chris-archimedeanco)]

Spoke too soon. Finally got a 504.

[Chris Rossi (chris-archimedeanco)]

Sorry, wrong ticket.