[Zope-dev] Zope3 sessions and database conflicts

[Ross Patterson]

Hermann Himmelbauer <dusty at qwer.tk> writes:

> Hi,
> For quite some time I see messages like this in my z3.log:
>
> 2010-03-02T16:27:14 WARNING ZopePublication Competing writes/reads 
> at /BSPSite/act/++vh++http:zis.act.at:80/bankneu/++/images/sponsor_logo.png: 
> database conflict error (oid 0x063f, class BTrees.OOBTree.OOBucket, serial 
> this txn started with 0x038484dc7d5ac044 2010-03-02 14:52:29.379960, serial 
> currently committed 0x038484ff3c6b5455 2010-03-02 15:27:14.160763)

I note the conflict happened when the request was just for an image.
I've seen this before under Zope2 when a PAS plugin was mis-using the
session machinery as a cache during authentication of the request.  When
ever a session object is accessed it initiates a write transaction in
the ZODB.  With most, if not all, authentication methods, when a user is
logged-in the auth tokens are included in every request which means
every request from the logged-in user invokes the authentication
machinery, including requests for images.  Since every page load
involves multiple requests for page resources, the database gets
overwhelmed with write transactions which inevitably conflict.  When the
write conflict occurs, the publisher appropriately retries the request
which multiplies the number of requests which multiplies the load which
increases the amount of time taken in processing requests which
multiplies the likelihood of write conflicts and your off to the races
in the wrong direction.

So I'd suggest you find out what in a request for a simple resource
(images, non-dynamic CSS or JS) is initiating the write transaction by
invoking sessions.  It's likely there's an inappropriate use of sessions
there.

HTH,
Ross

> I followed an advice from the zope-dev list and added some debug messages in  
> ZODB.Connection.py where the objects are registered for writing. 
>
> The following debug messages (I print the key/values of the object in 
> question) occur before and after the database conflict error:
>
> -------------------
> 2010-03-02T16:27:14 DEBUG zbsp keys: 
> ['6ZZzgjNK0p.bIIlruXb4JkDo-T0J-XipPcVFGtcj0
> LH6dMdI9akYvg', ......... , '7MmOPQOlkAHoa3T
> nydH9IIgKBqoVyn3Q.yH6OXJeLj7epObIy3M5Lg']
> -----------
> 2010-03-02T16:27:14 DEBUG zbsp values: [<zope.session.session.SessionData 
> object at 0x43723bec>, <zope.session.session.SessionData object at 
> 0x4372356c>, <zope.session.session.SessionData object at 0x437233ec>, 
> .........
> <zope.session.session.SessionData object at 0x436b586c>, 
> <zope.session.session.SessionData object at 0x436b532c>, 
> <zope.session.session.SessionData object at 
> 0x43640b6c>,<zope.session.session.SessionData object at 0x436b572c>]
> -------------------
>
> So it seems these are the session data containers.
>
> I wonder why they are written? Perhaps this happens when somebody else is 
> logging into the system (so a new session is added) and others are 
> concurrently reading from the session? However, this would mean that the 
> session mechanism has a flaw, as this is a standard procedure?
>
> Any ideas of how to fix this?
>
> Best Regards,
> Hermann