[Zope] Zope 2.8.4 - ZEO ClientStorage cache problem

Maciej Wisniowski maciej.wisniowski at coig.katowice.pl
Wed Apr 7 08:58:49 EDT 2010


Hi!

I have a problem with my instances of Zope 2.8.4: recently they started 
to run slowly. Restarting doesn't help much.
After observing Zope threads with DeadlockDebugger we found that very 
often threads are stuck while trying to access to ZEO cache file.

We have ZEO server and 2 ZEO clients. Each client has 10 threads. 
Example output from DeadlockDebugger (attached at the end of this 
message) shows that a lot of threads is executing self._lock.release() 
in loadEx function. Attached dump is from ZEO Client instance.
I wonder how it is possible that so much threads in this dump are 
releasing lock in the same time? Shouldn't they stay on acquire?


We did more dumps from DeadlockDebugger. Almost every time dump shows 
that there are some threads that are doing something in loadEx, like:
(...)
File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in loadEx
    self._lock.release()
  File "/opt/Zope/2.8.4/lib/python/ZEO/cache.py", line 194, in load
    return o.data, tid, o.version
  File "/opt/Zope/2.8.4/lib/python/ZEO/cache.py", line 1010, in access
    return Object.fromFile(self.f, key)

Seems to me that access to ZEO cache is a deadlock there, but I don't 
know why. Why it is so often and so slow(?) that I can see it in 
DeadlockDebugger almost every time? I don't remember seeing loadEx on 
output from DeadlockDebugger before.

I've checked disk I/O and it is ok. Event log shows:

2010-04-07T13:48:03 WARNING ZODB.DB DB.open() has 13 open connections 
with a pool_size of 7

which is our bad, as we have 10 threads and too small pool_size=7, but 
I'm not sure if this matters. I wonder that maybe, under heavy load, 
when sometimes all 10 threads are used, Zope has to continuosly create 
and destroy Connection objects and this causes "filling/flushing" their 
caches - I have no idea if this works that way?

Any ideas what might be wrong, or what can I check?


Threads traceback dump at 2010-04-07 12:08:06

Thread -179496032 (GET /VirtualHostBase/https/(...)/index_html):
  File "/opt/Zope/2.8.4/lib/python/ZServer/PubCore/ZServerPublisher.py", 
line 23, in __init__
    response=response)
  File 
"/opt/Zope/instancje/xyz_app/Products/ZopeProfiler/MonkeyPatcher.py", 
line 35, in __call__
    return self._function(*args,**kw)
  File 
"/opt/Zope/instancje/xyz_app/Products/ZopeProfiler/ZopeProfiler.py", 
line 357, in _profilePublishModule
    request=request, response=response)
  File "/opt/Zope/2.8.4/lib/python/ZPublisher/Publish.py", line 386, in 
publish_module
    environ, debug, request, response)
  File "/opt/Zope/2.8.4/lib/python/ZPublisher/Publish.py", line 187, in 
publish_module_standard
    response = publish(request, module_name, after_list, debug=debug)
  File "/opt/Zope/2.8.4/lib/python/ZPublisher/Publish.py", line 113, in 
publish
    request, bind=1)
  File "/opt/Zope/2.8.4/lib/python/ZPublisher/mapply.py", line 88, in mapply
    if debug is not None: return debug(object,args,context)
  File "/opt/Zope/2.8.4/lib/python/ZPublisher/Publish.py", line 40, in 
call_object
    result=apply(object,args) # Type s<cr> to step into published object.
  File 
"/opt/Zope/instancje/xyz_app/Products/App/MainController/MainController.py", 
line 248, in index_html
    return context.index_html_( *l, **d )
  File "/opt/Zope/2.8.4/lib/python/Shared/DC/Scripts/Bindings.py", line 
311, in __call__
    return self._bindAndExec(args, kw, None)
  File "/opt/Zope/2.8.4/lib/python/Shared/DC/Scripts/Bindings.py", line 
348, in _bindAndExec
    return self._exec(bound_data, args, kw)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PythonScripts/PythonScript.py", 
line 323, in _exec
    result = f(*args, **kw)
  File "Script (Python)", line 99, in index_html_
  File "/opt/Zope/2.8.4/lib/python/Shared/DC/Scripts/Bindings.py", line 
311, in __call__
    return self._bindAndExec(args, kw, None)
  File "/opt/Zope/2.8.4/lib/python/Shared/DC/Scripts/Bindings.py", line 
348, in _bindAndExec
    return self._exec(bound_data, args, kw)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PageTemplates/ZopePageTemplate.py", 
line 256, in _exec
    result = self.pt_render(extra_context=bound_names)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PageTemplates/PageTemplate.py", 
line 104, in pt_render
    tal=not source, strictinsert=0)()
  File "/opt/Zope/2.8.4/lib/python/TAL/TALInterpreter.py", line 206, in 
__call__
    self.interpret(self.program)
  File "/opt/Zope/2.8.4/lib/python/TAL/TALInterpreter.py", line 250, in 
interpret
    handlers[opcode](self, args)
  File "/opt/Zope/2.8.4/lib/python/TAL/TALInterpreter.py", line 609, in 
do_insertStructure_tal
    structure = self.engine.evaluateStructure(expr)
  File "/opt/Zope/2.8.4/lib/python/Products/PageTemplates/TALES.py", 
line 221, in evaluate
    return expression(self)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PageTemplates/ZRPythonExpr.py", 
line 47, in __call__
    return eval(code, g, {})
  File "Python expression "v['bodyDefinition']( 
index_html=v['index_html'])"", line 1, in <expression>
  File "/opt/Zope/2.8.4/lib/python/Shared/DC/Scripts/Bindings.py", line 
311, in __call__
    return self._bindAndExec(args, kw, None)
  File "/opt/Zope/2.8.4/lib/python/Shared/DC/Scripts/Bindings.py", line 
348, in _bindAndExec
    return self._exec(bound_data, args, kw)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PageTemplates/ZopePageTemplate.py", 
line 256, in _exec
    result = self.pt_render(extra_context=bound_names)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PageTemplates/PageTemplate.py", 
line 104, in pt_render
    tal=not source, strictinsert=0)()
  File "/opt/Zope/2.8.4/lib/python/TAL/TALInterpreter.py", line 206, in 
__call__
    self.interpret(self.program)
  File "/opt/Zope/2.8.4/lib/python/TAL/TALInterpreter.py", line 250, in 
interpret
    handlers[opcode](self, args)
  File "/opt/Zope/2.8.4/lib/python/TAL/TALInterpreter.py", line 609, in 
do_insertStructure_tal
    structure = self.engine.evaluateStructure(expr)
  File "/opt/Zope/2.8.4/lib/python/Products/PageTemplates/TALES.py", 
line 221, in evaluate
    return expression(self)
  File 
"/opt/Zope/2.8.4/lib/python/Products/PageTemplates/ZRPythonExpr.py", 
line 47, in __call__
    return eval(code, g, {})
  File "Python expression "here.controller()"", line 1, in <expression>
  File "/opt/Zope/2.8.4/lib/python/AccessControl/ZopeSecurityPolicy.py", 
line 35, in getRoles
    roles = getattr(value, '__roles__', _noroles)
  File "/opt/Zope/2.8.4/lib/python/ZODB/Connection.py", line 704, in 
setstate
    self._setstate(obj)
  File "/opt/Zope/2.8.4/lib/python/ZODB/Connection.py", line 760, in 
_setstate
    self._reader.setGhostState(obj, p)
  File "/opt/Zope/2.8.4/lib/python/ZODB/serialize.py", line 495, in 
setGhostState
    state = self.getState(pickle)
  File "/opt/Zope/2.8.4/lib/python/ZODB/serialize.py", line 488, in getState
    return unpickler.load()
  File "/opt/Zope/2.8.4/lib/python/ZODB/serialize.py", line 436, in 
_persistent_load
    return self._conn.get(oid)
  File "/opt/Zope/2.8.4/lib/python/ZODB/Connection.py", line 207, in get
    p, serial = self._storage.load(oid, self._version)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 749, in 
loadEx
    self._lock.acquire()    # for atomic processing of invalidations

Thread 156433312 (GET /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 751, in 
loadEx
    t = self._cache.load(oid, version)

Thread 92818336 (GET /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

Thread 113798048 (POST /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

Thread 103308192 (POST /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

Thread 145943456 (GET /VirtualHostBase/https/...):
  (...)
  File "/usr/local/lib/python2.3/codecs.py", line 400, in write
    return self.writer.write(data)
  File "/usr/local/lib/python2.3/codecs.py", line 179, in write
    self.stream.write(data)

Thread 41311136 (POST /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

Thread 133561248 (GET /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

Thread 61971360 (GET /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

Thread 74673056 (GET /VirtualHostBase/https/...):
  (...)
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 746, in load
    return self.loadEx(oid, version)[:2]
  File "/opt/Zope/2.8.4/lib/python/ZEO/ClientStorage.py", line 755, in 
loadEx
    self._lock.release()

End of dump


-- 
Maciej Wiśniowski


More information about the Zope mailing list