Anforderungen
Zope 2.12
Für Zope 2.10 ist ein Backport der Publication Events verfügbar in
ZPublisherEventsBackport. Dieser wird benötigt und lässt sich mit Buildout einfach durch plone.postpublicationhook unter Angabe von [Zope2.10] installieren:
eggs = … plone.postpublicationhook [Zope2.10]
Installation
Um haufe.requestmonitoring zu installieren, muss es einfach in der buildout.cfg-Datei den zcml-Optionen im Instanz-Abschnitt hinzugefügt werden:
[instance-base] … eggs += … haufe.requestmonitoring threadframe zope.app.appsetup zcml += … haufe.requestmonitoring
Aktivierung
Zur Aktivierung von haufe.requestmonitoring erhält die Instanz einen Abschnitt product-config mit dem Namen successlogging und dem Schlüssel filebase. Dieser gibt den Basisnamen der Log-Dateien an, in unserem Fall request:
[instance-base] … zope-conf-additional = <product-config successlogging> filebase /home/veit/vs_buildout/var/log/request </product-config> %import haufe.requestmonitoring <requestmonitor requestmonitor> period 5s <monitorhandler dumper> factory haufe.requestmonitoring.DumpTraceback.factory # 0 means no repetition. # A negative value means indefinitely. repeat -1 time 10s </monitorhandler> </requestmonitor>
Beim Logging werden dann zwei Dateien unterschieden: <base>_good.<date> und <base>_bad.<date>. Üblicherweise werden Antwortzeiten über 500 ms als unsuccessful bezeichnet. Falls dieser Standardwert geändert werden soll, kann ein spezieller ISuccessFull-Adapter registriert werden.
Nachdem das Buildout-Skript durchlaufen und der ZEO-Cluster neu gestartet wurde, sind die Subscriber IPubStart und IPubSuccess bzw. IPubFailure registriert. Für jedes dieser Events wird nun ein Eintrag in die Log-Datei geschrieben in der Form:
timestamp status request_time type request_id request_info
Monitoring
Mit DumpTraceback werden diejenigen Anfragen protokolliert, die nach der in period angegebenen Zeit nach Anfragen sucht, die länger laufen als die in time angegebene Zeit:
%import haufe.requestmonitoring <requestmonitor requestmonitor> period 5s <monitorhandler dumper> factory Haufe.RequestMonitoring.DumpTraceback.factory # 0 --> no repetition repeat -1 time 10s </monitorhandler> </requestmonitor>
Eine typische Ausgabe sieht dann so aus:
2009-08-11 14:29:09 INFO Zope Ready to handle requests 2009-08-11 14:29:09 INFO RequestMonitor started 2009-08-11 14:29:14 INFO RequestMonitor monitoring 1 requests 2009-08-11 14:29:19 INFO RequestMonitor monitoring 1 requests 2009-08-11 14:29:24 INFO RequestMonitor monitoring 1 requests 2009-08-11 14:29:24 WARNING RequestMonitor.DumpTrace Long running request Request 1 "/foo" running in thread -497947728 since 14.9961140156s Python call stack (innermost first) Module /home/junga/sandboxes/review/parts/instance/Extensions/foo.py, line 4, in foo Module Products.ExternalMethod.ExternalMethod, line 231, in __call__ - __traceback_info__: ((), {}, None) Module ZPublisher.Publish, line 46, in call_object Module ZPublisher.mapply, line 88, in mapply Module ZPublisher.Publish, line 126, in publish Module ZPublisher.Publish, line 225, in publish_module_standard Module ZPublisher.Publish, line 424, in publish_module Module Products.ZopeProfiler.ZopeProfiler, line 353, in _profilePublishModule Module Products.ZopeProfiler.MonkeyPatcher, line 35, in __call__ Module ZServer.PubCore.ZServerPublisher, line 28, in __init__