[Zope-dev] Re: Preliminary findings: Zope 2.7 leakage caused by errors

Thu May 20 09:58:38 EDT 2004

Juan David,

I'm using 1.0.1 ... I'm just abotu to try and test with 1.1.0a3 ...

BTW, does that mean it's alpha software or something? is 1.1.0 stable?

If the problem comes from Localizer I suspect this patch might be the cause:

def new_publish(request, module_name, after_list, debug=0): 
    id = get_ident() 
    print "Localizer got thread id: " + str(id)
    Publish._requests[id] = request 
    print "Request dict is now: " + str(Publish._requests)   
    x = Publish.old_publish(request, module_name, after_list, debug) 
    try:
        del Publish._requests[id]
    except KeyError:
        # XXX 
        # Some people has reported that sometimes a KeyError exception is
        # raised in the previous line, I haven't been able to reproduce it.
        # This try/except clause seems to work. I'd prefer to understand
        # what is happening.
        LOG('Localizer', PROBLEM,
            "The thread number %s don't has a request object associated." %
id)
    except:
        print "Localizer got an exception" 

    return x 

What happens if an exception occurs here:

    x = Publish.old_publish(request, module_name, after_list, debug) 

??

If some clean up code is supposed to occur it might be held back by the fact
that
there's a reference to the request kept in the global dictionary ...
At least that's my theory :)
But then I'm mostly uneducated about the intricacies of exception handling
at this
level, though I've been forced to learn quickly :)

I'd be curious to know at least if you can reproduce the leak by generating
loads
of errors on a Localizer enabled site?

One option would also be to simply wrap it in a try:catch and see what
happens there
... But I noticed 1.1.0a3 uses a different model for wrapping the request,
so that
just might do the trick.

Thanks for a very cool and useful product BTW.  This is combination with the
TranslationService is saving me loads of time.

Cheers,
J.F.

-----Original Message-----
From: zope-dev-bounces at zope.org [mailto:zope-dev-bounces at zope.org]On
Behalf Of "J. David Ibáñez"
Sent: May 20, 2004 6:47 AM
To: Tres Seaver
Cc: Jean-Francois.Doyon at ccrs.nrcan.gc.ca; brian at zope.com;
chrism at plope.com; zope-dev at zope.org
Subject: [Zope-dev] Re: Preliminary findings: Zope 2.7 leakage caused by
errors

Localizer (1.0.1) dynamically patches Zope, it stores a dictionary in 
the module
"ZPublisher.Publish". The keys are integers, they are the values 
returned by Python's
"thread.get_ident". The values are "ZPublisher.HTTPRequest.HTTPRequest"
instances, they are not acquisition wrappers.

Jean-François, which Localizer version do you use? Just to be sure we 
look at
the same code.

Tres Seaver wrote:

> Jean-Francois.Doyon at CCRS.NRCan.gc.ca wrote:
>
>> Gents,
>>
>> In following to the discussions regarding the leakage zope.org and my 
>> site
>> suffer from, I've done some testing, and here's what I've found.
>>
>> First of all, the leak does seem to occur when errors occur.  Unlike 
>> what
>> Chris suggested, I still suffer from this leak even when I completely
>> remove standard_error_message.
>>
>> How I tested:
>>
>> I use JMeter, and a 99% identical box, dedicated for testing:
>>
>> - RH 7.3
>> - Python 2.3.3 compiled with ./configure and no options
>> - Zope 2.7 + a variety of products, both custom and well known (CMF,
>> Localizer, etc ...)
>>
>> I look at my error log on my main site to see the types of errors 
>> coming up
>> and note the URL/parameters.
>> Such errors include KeyErrors, a RecursionDepth error, a
>> Method-something-or-other error, and so on.
>>
>> I setup JMeter with multiple concurrent threads and run it.  Within 
>> minutes
>> I can see refcounts growing abnormally on the test server.
>>
>> I then shut everything down and minimize the caches.  The following 
>> are left
>> around that shouldn't be:
>>
>> Class  May 19, 2004 1:52 pm  May 19, 2004 2:26 pm  Delta  
>> Acquisition.ImplicitAcquirerWrapper  1025  1309  +284  
>> ZServer.HTTPResponse.ZServerHTTPResponse  150  247  +97  
>> ZPublisher.BaseRequest.RequestContainer  146  240  +94  
>> ZPublisher.HTTPRequest.HTTPRequest  172  262  +90
>>
>> Right now I've focused on finding out why the Requests are still around.
>>
>> Using the gc module, I've found that all leaked requests are being 
>> held by a
>> dictionary.  If I look at said dictionaries, this is what they might 
>> look
>> like:
>>
>> {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/francais/mapsatoz>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/francais/mapsatoz>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/search/political>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/search/political>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/search/political>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/search/political>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/search/political>},
>>  {3075: <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/maps/peopleandsociety/age/youth/HEAD>,
>>   4100: <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/debug>,
>>   5125: <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/debug>,
>>   6150: <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/english/search/political>,
>>   7175: <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/vh_

>>
>> site/english/maps/archives/5thedition/other/referencemaps>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/debug>},
>>  {'REQUEST': <HTTPRequest,
>>
URL=/VirtualHostBase/http/atlastest2.ccrs.nrcan.gc.ca:80/VirtualHostRoot/_vh

>>
>> _site/misc_/WFSAdapter/sqlmethod.gif>}
>
>
> I know that the Localizer product does (or used to do) some kind of 
> magic to make the REQUEST available to code as a "global".  Can you 
> reproduce this data without that product present?
>
>>
>> NOTE: I had to hack the __repr__ of HTTPRequest not to use 
>> self['URL'] since
>> it seems that attribute is unavailable in a closed request.  I use 
>> PATH_INFO
>> instead.
>>
>> Most of the time I get the dictionary with the 'REQUEST' key.  Those
>> dictionaries with int's as keys are ones generated by the 
>> ExternalMethod I
>> use to run the code to debug ... So even errors raised while trying 
>> to debug
>> this leaks a dictionary that holds on to the request(s).
>>
>> Said dictionary does not seem to be referred to by anything, at least 
>> not
>> anything the gc module can find (gc.get_referrers()).  One possible
>> situation is that said dictionary is actually part of the 
>> HTTPRequest, and
>> we have a cyclic reference problem.  I don't think so however, I've 
>> looked
>> at the HTTPRequest instances, and they have nothing in them other than
>> strings, lists, basic dict's and an HTTPResponse instance.  I'll take
>> another look to be sure.
>
>
> Again, I would be looking at the Localizer's module-level globals for 
> this one.
>
>> Next step is too look at the Wrappers and see what they're all about and
>> what's holding them there.
>
>
> The wrappers are almost certainly there because the request is holding 
> on to objects, which hold on to others, etc.
>
>> I'm hoping this information might give a clue to someone who knows Zope
>> error handling better than I as to what might be the problem here ... 
>> Also I
>> understand zope.org suffers from this? :)
>>
>> Based on this information also, I have no reason to believe this is 
>> caused
>> by product code ... I have to guess it's a Zope bug?
>>
>> In some ways this is motivating me to reduce the number of errors 
>> that could
>> occur, but because ALL errors seems to cause the problem, I 
>> ultimately have
>> no control over it and under certain circumstances I suffer heavily from
>> this.  404's alone probably cause this (I'm plannign to test that
>> explicitely as well).
>>
>> Thoughts, suggestions, comments welcome ...
>
>
> I am CC'ing Juan-David, in case he may be able to offer any insights 
> from the perspective of the Localizer product.
>
> Tres.

-- 
J. David Ibáñez
Founder and CTO of Itaapy <http://www.itaapy.com>
9 rue Darwin, 75018 Paris
Tel +33 (0)1 42 23 67 45 / Fax +33 (0)1 53 28 27 88 

_______________________________________________
Zope-Dev maillist  -  Zope-Dev at zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )