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