Plone висит на Python waiter.acquire() и использует 100% CPU
Мы сталкиваемся с некоторыми препятствиями в нашем экземпляре Plone, когда менеджеры контента выполняют такие действия, как извлечение, редактирование, переходы рабочего процесса и так далее. Пока что нам не удалось выделить что-то конкретное, и это происходит периодически.
Для собственного тестирования я придерживался действия "Извлечь" и использую Products.LongRequestLogger для устранения неполадок. Я вижу, как действие заняло от 8 до 78 секунд в зарегистрированных результатах, а также пользовательский опыт. Вот обратная трассировка, которая повторяется в LongRequestLogger:
Traceback:
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/ZServer/PubCore/ZServerPublisher.py", line 31, in __init__
response=b)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/ZPublisher/Publish.py", line 455, in publish_module
environ, debug, request, response)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.LongRequestLogger-1.1.0-py2.7.egg/Products/LongRequestLogger/patch.py", line 16, in wrapper
result = wrapper.original(*args, **kw)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/ZPublisher/Publish.py", line 249, in publish_module_standard
response = publish(request, module_name, after_list, debug=debug)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/ZPublisher/Publish.py", line 138, in publish
request, bind=1)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/ZPublisher/mapply.py", line 77, in mapply
if debug is not None: return debug(object,args,context)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/ZPublisher/Publish.py", line 48, in call_object
result=apply(object,args) # Type s<cr> to step into published object.
File "/var/db/zope/plone43/zeocluster/src/plone.app.iterate/plone/app/iterate/browser/checkout.py", line 77, in __call__
wc = policy.checkout(locator())
File "/var/db/zope/plone43/zeocluster/src/plone.app.iterate/plone/app/iterate/policy.py", line 65, in checkout
working_copy, relation = copier.copyTo( container )
File "/var/db/zope/plone43/zeocluster/src/plone.app.iterate/plone/app/iterate/copier.py", line 54, in copyTo
wc = self._copyBaseline( container )
File "/var/db/zope/plone43/zeocluster/src/plone.app.iterate/plone/app/iterate/copier.py", line 211, in _copyBaseline
result = container.manage_pasteObjects( clipboard )
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/OFS/CopySupport.py", line 235, in manage_pasteObjects
self._setObject(id, ob)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.BTreeFolder2-2.13.3-py2.7.egg/Products/BTreeFolder2/BTreeFolder2.py", line 455, in _setObject
notify(ObjectAddedEvent(ob, self, id))
File "/var/db/zope/plone43/buildout-cache/eggs/zope.event-3.5.2-py2.7.egg/zope/event/__init__.py", line 31, in notify
subscriber(event)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/event.py", line 24, in dispatch
zope.component.subscribers(event, None)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/_api.py", line 136, in subscribers
return sitemanager.subscribers(objects, interface)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/registry.py", line 321, in subscribers
return self.adapters.subscribers(objects, provided)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.interface-4.1.0-py2.7-linux-x86_64.egg/zope/interface/adapter.py", line 601, in subscribers
subscription(*objects)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/event.py", line 32, in objectEventNotify
zope.component.subscribers((event.object, event), None)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/_api.py", line 136, in subscribers
return sitemanager.subscribers(objects, interface)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/registry.py", line 321, in subscribers
return self.adapters.subscribers(objects, provided)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.interface-4.1.0-py2.7-linux-x86_64.egg/zope/interface/adapter.py", line 601, in subscribers
subscription(*objects)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/OFS/subscribers.py", line 110, in dispatchObjectMovedEvent
callManageAfterAdd(ob, event.object, event.newParent)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/OFS/subscribers.py", line 143, in callManageAfterAdd
ob.manage_afterAdd(item, container)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.ATContentTypes-2.1.13-py2.7.egg/Products/ATContentTypes/content/document.py", line 196, in manage_afterAdd
ATCTContent.manage_afterAdd(self, item, container)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/BaseContent.py", line 43, in manage_afterAdd
BaseObject.manage_afterAdd(self, item, container)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/BaseObject.py", line 158, in manage_afterAdd
Referenceable.manage_afterAdd(self, item, container)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/Referenceable.py", line 245, in manage_afterAdd
r.set(self, rrefs[r.getName()])
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/Field.py", line 1987, in set
tool.addReference(instance, uid, self.relationship, **addRef_kw)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/ReferenceEngine.py", line 340, in addReference
annotation._setObject(rID, referenceObject)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/OFS/ObjectManager.py", line 359, in _setObject
notify(ObjectAddedEvent(ob, self, id))
File "/var/db/zope/plone43/buildout-cache/eggs/zope.event-3.5.2-py2.7.egg/zope/event/__init__.py", line 31, in notify
subscriber(event)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/event.py", line 24, in dispatch
zope.component.subscribers(event, None)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/_api.py", line 136, in subscribers
return sitemanager.subscribers(objects, interface)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/registry.py", line 321, in subscribers
return self.adapters.subscribers(objects, provided)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.interface-4.1.0-py2.7-linux-x86_64.egg/zope/interface/adapter.py", line 601, in subscribers
subscription(*objects)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/event.py", line 32, in objectEventNotify
zope.component.subscribers((event.object, event), None)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/_api.py", line 136, in subscribers
return sitemanager.subscribers(objects, interface)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.component-3.9.5-py2.7.egg/zope/component/registry.py", line 321, in subscribers
return self.adapters.subscribers(objects, provided)
File "/var/db/zope/plone43/buildout-cache/eggs/zope.interface-4.1.0-py2.7-linux-x86_64.egg/zope/interface/adapter.py", line 601, in subscribers
subscription(*objects)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/OFS/subscribers.py", line 110, in dispatchObjectMovedEvent
callManageAfterAdd(ob, event.object, event.newParent)
File "/var/db/zope/plone43/buildout-cache/eggs/Zope2-2.13.21-py2.7.egg/OFS/subscribers.py", line 143, in callManageAfterAdd
ob.manage_afterAdd(item, container)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/ReferenceEngine.py", line 145, in manage_afterAdd
rc.catalog_object(self, url)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.Archetypes-1.9.4-py2.7.egg/Products/Archetypes/UIDCatalog.py", line 189, in catalog_object
ZCatalog.catalog_object(self, obj, uid, **kwargs)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.ZCatalog-2.13.23-py2.7.egg/Products/ZCatalog/ZCatalog.py", line 476, in catalog_object
update_metadata=update_metadata)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.ZCatalog-2.13.23-py2.7.egg/Products/ZCatalog/Catalog.py", line 320, in catalogObject
index = self.updateMetadata(object, uid, None)
File "/var/db/zope/plone43/buildout-cache/eggs/Products.ZCatalog-2.13.23-py2.7.egg/Products/ZCatalog/Catalog.py", line 276, in updateMetadata
while not data.insert(index, newDataRecord):
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py", line 860, in setstate
self._setstate(obj)
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py", line 901, in _setstate
p, serial = self._storage.load(obj._p_oid, '')
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py", line 1270, in load
return self._storage.load(oid, '')
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZEO/ClientStorage.py", line 833, in load
data, tid = self._server.loadEx(oid)
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZEO/ServerStub.py", line 176, in loadEx
return self.rpc.call("loadEx", oid)
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZEO/zrpc/connection.py", line 763, in call
r_args = self.wait(msgid)
File "/var/db/zope/plone43/buildout-cache/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZEO/zrpc/connection.py", line 791, in wait
self.replies_cond.wait()
File "/var/db/zope/plone43/Python-2.7/lib/python2.7/threading.py", line 339, in wait
waiter.acquire()
В течение этого времени я замечаю, что клиент использует максимум на 100% загрузки ЦП, и это приводит к замедлению сканирования сайта, если не к полной остановке. Я наблюдал это в нашей производственной среде, в которой одновременно может быть от 5 до 40 пользователей. Поэтому я проверил это в локальной версии нашего сайта, и даже с одним пользователем я вижу те же результаты.
Мы запускаем Plone 4.3.2 на 64-битной коробке RedHat 5.10 (Tikanga). Моя локальная виртуальная машина работает под управлением CentOS 5.10 с той же версией Plone. В нашей производственной среде мы используем два сервера: один предназначен для работы с Zeoserver, а второй - для 4 клиентов.
Я не могу понять, почему он висит здесь и потребляет так много ресурсов. Любые предложения или решения будут высоко ценится!
ОБНОВЛЕНИЕ Мы недавно обновили Plone 4.2 до Plone 4.3, и кажется, что эта проблема либо началась в то время, либо, по крайней мере, значительно возросла. Мы используем собственные темы и типы контента, но они основаны на ATContentTypes, и мы сделали то, что нам нужно, чтобы они работали с Plone 4.3.
РЕДАКТИРОВАТЬ Я изменил уровень ведения журнала сервера ZEO на DEBUG, и это было все, что я получил:
2014-05-28T14:38:35 (unconnected) disconnected
2014-05-28T14:38:44 new transaction
2014-05-28T14:38:44 (192.168.56.102:54486) ('1') lock: transactions waiting: 0
2014-05-28T14:38:44 (192.168.56.102:54486) Preparing to commit transaction: 2 objects, 763 bytes
2014-05-28T14:38:44 new transaction
2014-05-28T14:38:44 (192.168.56.102:54486) ('1') lock: transactions waiting: 0
2014-05-28T14:38:44 (192.168.56.102:54486) Preparing to commit transaction: 1 objects, 123 bytes
2014-05-28T14:39:22 new transaction
2014-05-28T14:39:22 (192.168.56.102:54474) ('1') lock: transactions waiting: 0
2014-05-28T14:39:22 (192.168.56.102:54474) Preparing to commit transaction: 885 objects, 458894 bytes
2014-05-28T14:40:44 new transaction
2014-05-28T14:40:44 (192.168.56.102:54486) ('1') lock: transactions waiting: 0
2014-05-28T14:40:44 (192.168.56.102:54486) Preparing to commit transaction: 1 objects, 123 bytes
Согласно Client1 LongRequest.log действие (Check out) началось в 14:39:07 и закончилось в 14:39:28 (это было одно из самых быстрых времен ответа).