Using the Zope Debug Log to Track Down Hangs

Created by . Last modified on 2003/08/01.

Note that this script has been superseded by requestprofiler.py (downloadable separately here), which is a part of Zope 2.4. Documentation for the requestprofiler script is available via its --help switch.

This is for Zope 2.X... you can turn on detailed debug logging inside z2.py by using the "-M" switch to z2.py. (see z2.py for more detail) Restart the Zope server. Then create the following debug.log analyzer script:

import string, sys

def analyze(f):
    requests={}
    while 1:
        line=f.readline()
        line=string.strip(line)
        if not line:
            break
        code, id = string.split(line)[:2]
        codes=requests.get(id, [])
        codes.append(line)
        if len(codes) == 4:
            del requests[id]
            print '.',
        else:
            requests[id]=codes
    print
    for id, l in requests.items():
        print 'request', id, 'did not end\n', string.join(l, '\n'), '\n'
            
if __name__=='__main__':
    analyze(open(sys.argv[1]))

The logfile you specified in the -M argument to z2.py will start to pile up. When you come across a few hangs, run the debug log file through the analyzer script. You will see on which methods the site is taking a long time. Investigate those methods.

Thanks to Amos Latteier for the debug log analyzer script...