For the moment only a reverse proxy (apache, ngnix) or a browser can show you how long a request took to be processed.

For monitoring or debugging purpose you might want to know what zope instance is slow.

The default access zope log file give you such a log format:

127.0.0.1 - Anonymous [27/Oct/2010:16:44:04 +0100] "GET / HTTP/1.1" 200 1957 "" "Mozilla/5.0 (X11; U; Linux x86_64; fr; rv:1.9.2.11) Gecko/20101013 Ubuntu/10.10 (maverick) Firefox/3.6.11"

which doesn’t give you any information about how fast zope was to serve that request.

At the moment there is no way to add this number of seconds in the log format of zope 2. Unfortunately the zope http server (ZServer & medusa) cannot be easily overridden or monkey patched.

Here is a patch to apply on your zope 2 buildout to have such a log format:

127.0.0.1 0.008843 - Anonymous [27/Oct/2010:16:45:41 +0100] "GET / HTTP/1.1" 200 1957 "" "Mozilla/5.0 (X11; U; Linux x86_64; fr; rv:1.9.2.11) Gecko/20101013 Ubuntu/10.10 (maverick) Firefox/3.6.11"

You see here that it took 0.008843 seconds to compute the page on that zope instance.

Thanks to this number of seconds we have monitoring checks (using Nagios 3) and monitoring graph (using Cacti) of each instances within our zeo’s.

Patch for Zope 2.10

Patch for Zope 2.12

To apply the patch, install omelette in your buildout and run this command in the root of your buildout:

patch -p0 < responsetime-212.diff

It will patch the required methods in ZServer to give you the number of seconds the request took to be processed. A patch might sound (and is) hacky but that’s the easiest way to change such a low level module.

Maybe we should give the possiblility to have this in log format in Zope 2.1 / 2.13 default config ?