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
