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 scr 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
