Re: [Zope-dev] Zope3 sessions and database conflicts
On 03/04/2010 11:08 PM, Ross Patterson wrote: Hermann Himmelbauer du...@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. I remember one thing about sessions where just the access to the session would create a new session even if it was never touched. The API actually provides two invokations: one to get a session and create if not existing, the other got get a session and raise a KeyError instead of creating a new one. -- Christian Theune · c...@gocept.com gocept gmbh co. kg · forsterstraße 29 · 06112 halle (saale) · germany http://gocept.com · tel +49 345 1229889 0 · fax +49 345 1229889 1 Zope and Plone consulting and development ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
[Zope-dev] Zope3 sessions and database conflicts
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 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 -- herm...@qwer.tk GPG key ID: 299893C7 (on keyservers) FP: 0124 2584 8809 EF2A DBF9 4902 64B4 D16B 2998 93C7 ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
Re: [Zope-dev] Zope3 sessions and database conflicts
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 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 -- herm...@qwer.tk GPG key ID: 299893C7 (on keyservers) FP: 0124 2584 8809 EF2A DBF9 4902 64B4 D16B 2998 93C7 ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope ) ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
Re: [Zope-dev] Zope3 sessions and database conflicts
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 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? I had a serious problem with the session machinery. I use a very long timeout on sessions and thus have a large number of sessions saved (up to 30k). The sweep machinery kicks in and sweeps everything. It takes so long that all the threads do the sweep and you get these errors. I customised the sweep for my site as follows: 1. Only sweep at night 2. Sweep a random subset of the data (20 records), but sweep very often 3. Different timeouts for authenticated sessions and anonymous sessions. Regards, Kevin Best Regards, Hermann -- herm...@qwer.tk GPG key ID: 299893C7 (on keyservers) FP: 0124 2584 8809 EF2A DBF9 4902 64B4 D16B 2998 93C7 ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope ) ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
Re: [Zope-dev] Zope3 sessions and database conflicts
Could you please, Kevin, explain how you acheived that ? Thank you - Souheil 2010/3/4 kevin gill ke...@movieextras.ie: 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 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? I had a serious problem with the session machinery. I use a very long timeout on sessions and thus have a large number of sessions saved (up to 30k). The sweep machinery kicks in and sweeps everything. It takes so long that all the threads do the sweep and you get these errors. I customised the sweep for my site as follows: 1. Only sweep at night 2. Sweep a random subset of the data (20 records), but sweep very often 3. Different timeouts for authenticated sessions and anonymous sessions. Regards, Kevin Best Regards, Hermann -- herm...@qwer.tk GPG key ID: 299893C7 (on keyservers) FP: 0124 2584 8809 EF2A DBF9 4902 64B4 D16B 2998 93C7 ___ Zope-Dev maillist - zope-...@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope ) ___ Zope-Dev maillist - zope-...@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope ) ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
Re: [Zope-dev] Zope3 sessions and database conflicts
Hermann Himmelbauer du...@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 ___ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
