[ZODB-Dev] Re: [Zope-dev] Re: [Bug] ZODB invalidation processing
one very important finding: tryToResolveConflict fails in the resolve function resolve built-in method _p_resolveConflict of BTrees._IOBTree.IOBucket object at 0xb1ab82b4 by raising an exception, when I call it again from the debugger I get. (Pdb) resolved = resolve(old, committed, newstate) *** BTreesConflictError: BTrees conflict error at -1/47/47: Conflicting inserts So that is the real error. -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
[ZODB-Dev] Re: [Bug] ZODB invalidation processing
Tres Seaver schrieb:
-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1
Not if the sessions being used are from 'faster' -- it doesn't use
IOBTree. The major application use of that module is in the catalog.
you correct see below:
Try dumping out the contents of the bucket:
for k, v in bucket.items():
print k, type(v)
resolve built-in method _p_resolveConflict of BTrees._IOBTree.IOBucket
object at 0xb1ab82b4
print root._p_jar[p64(0xb1ab82b4)]
*** POSKeyError: ZODB.POSException.POSKeyError instance at 0xa8f9e6cc
with the recepies here http://www.zopelabs.com/cookbook/1114086617
I was able to get the information about the oid, which is passed to
tryToResolveConflict, here is the result
BTrees._IOBTree.IOBTree object at 0xb562fadc
DateIndex at created
Products.ZCatalog.Catalog.Catalog object at 0xb12d622c
CatalogTool at portal_catalog
CPSDefaultSite at uniben
Application at
{'Application': Application at , 'ZGlobals': BTrees._OOBTree.OOBTree
object at 0xb2739224}
What does this tell us ?
--
Gruß Joachim
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/
ZODB-Dev mailing list - ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev
Re: [ZODB-Dev] Re: [Zope-dev] Re: [Bug] ZODB invalidation processing
some more findings: 1. The conflict error really happens on the Portalcatalog 2. It is a BTreesConflictError: BTrees conflict error at -1/47/47: Conflicting inserts which disguised as ConflictError, through the various try: excepts: 3. It happens on DateIndexes like created and modified. 4. I put for a test: try: resolved = resolve(old, committed, newstate) except: return invalidated into tryToResolveConflict and into the store-method of FileStorage: if serial != cached_tid: rdata = self.tryToResolveConflict(oid, cached_tid,serial, data) if rdata is None: raise POSException.ConflictError(oid=oid, serials=(cached_tid, serial), data=data) elif rdata == invalidated: #new for test old = False # pass # With these hacks I get rid of the conflictErrors. But when I delete the created Items I get: 2007-06-01 13:20:33 ERROR Zope.UnIndex DateIndex: unindex_object tried to retrieve set 1075379718 from index created but couldn't. This should not happen. 2007-06-01 13:20:33 ERROR Zope.UnIndex DateIndex: unindex_object tried to retrieve set 1075379838 from index Date but couldn't. This should not happen. 2007-06-01 13:20:33 ERROR Zope.UnIndex DateIndex: unindex_object tried to retrieve set 1075379719 from index modified but couldn't. This should not happen. So obviously I just fix the symptom with this hack. I think the real cause: lies in these lines: if old: cached_tid = self._get_cached_tid(oid) if cached_tid is None: h = self._read_data_header(old, oid) if h.version: if h.version != version: raise VersionLockError(oid, h.version) pnv = h.pnv cached_tid = h.tid if serial != cached_tid: rdata = self.tryToResolveConflict(oid, cached_tid,serial, data) Which is also supported by the fact, that on our live system which is running on 4 zeo-clients we get this traceback: 2007-06-01T12:38:59 ERROR Zope.SiteErrorLog http://uniben.waeup.org/campus/students/F541700/study_course/create_level Traceback (innermost last): Module Zope2.App.startup, line 173, in zpublisher_exception_hook Module ZPublisher.Publish, line 121, in publish Module Zope2.App.startup, line 240, in commit Module transaction._manager, line 96, in commit Module Products.CPSCompat.PatchZODBTransaction, line 175, in commit Module transaction._transaction, line 436, in _commitResources Module ZODB.Connection, line 665, in tpc_vote Module ZEO.ClientStorage, line 893, in tpc_vote Module ZEO.ClientStorage, line 877, in _check_serials ConflictError: database conflict error (oid 0x8fe833, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036e0418ddcccf55 2007-06-01 11:36:51.984384, serial currently committed 0x036e041a3a33e311 2007-06-01 11:38:13.641254) Any suggestion for a temporary fix would be very welcome, since we get about 6000 conflict errors per day now about 15 % unresolved, and they are really killing our portal. -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
[ZODB-Dev] Re: [Bug] ZODB invalidation processing
Tres Seaver schrieb:
BTrees._IOBTree.IOBTree object at 0xb562fadc
DateIndex at created
Products.ZCatalog.Catalog.Catalog object at 0xb12d622c
CatalogTool at portal_catalog
CPSDefaultSite at uniben
Application at
{'Application': Application at , 'ZGlobals': BTrees._OOBTree.OOBTree
object at 0xb2739224}
What does this tell us ?
That is a real conflict: both transactions have inserted values into
the 'created' date index's '_index' under the same key, which can't be
resolved. Retrying the transaction is the only choice here.
Because DateIndexes convert the indexed value to an integer with
precision of one minute,
really one minute or do you mean second.
a date index on 'created' is fairly likely to
generate such conflicts when two parties both create content at the same
time.
But then I wonder how a CMF site could ever work, this error shows up
already on my lokal system when to users add something. On our live
system it is killing our portal ?
I would consider this a bug.
Ideally, one would examine the two values being inserted, note that they
were both IITreeSet instances containing one int apiece, and exploit our
knowledge of the application semantics to merge them, removing the
conflict; however, *because* they are IITreeSets, and therefore
separate persistent objects, their state is not available to the
bucket's '_p_resolveConflict', which must therefore lose.
--
Gruß Joachim
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/
ZODB-Dev mailing list - ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev
[ZODB-Dev] Re: [Bug] ZODB invalidation processing
Dieter Maurer schrieb: Perry wrote at 2007-5-25 13:16 +0200: database conflict error (oid 0x7905e6, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036ddc2a44454dee 2007-05-25 09:14:16.000950, serial currently committed 0x036ddc2c21950377 2007-05-25 09:16:07.870801) (80 conflicts (10 unresolved) since startup at Fri May 25 05:19:08 2007) ... ConflictError: database conflict error (oid 0x7905e6, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036ddc2b3e989fdd 2007-05-25 09:15:14.670982, serial currently committed 0x036ddc2dd48f4e33 2007-05-25 09:17:49.818700) These log entries indicate a bug in ZODB's invalidation processing. The first entry tells us that the object was read at 9:14:16 and the modification conflicts with a write from 9:16:07. The second entry tells us that the object was read at 9:15:14 *BUT* at the time this transaction has started, the ZODB should already have known the modification from 9:16:07 and the object read at 9:15:14 should have been invalidated. The new transaction should not have seen any state older than 9:16:07 (as it begins after this time). I could reproduce the conflict error on my local machine not using ZEO. I invoked the longrunning process create_level for two users after a zope-restart. here is the log: 2007-05-31 09:44:24 INFO Zope Ready to handle requests 2007-05-31 09:44:39 INFO Skins.create_level A923157 started to create level 200 2007-05-31 09:44:41 INFO Skins.create_level Y617041 started to create level 400 the next two entries are printed before the redirect/commit 2007-05-31 09:45:01 INFO Skins.create_level Y617041 finished to create level 400 2007-05-31 09:45:06 INFO Skins.create_level A923157 finished to create level 200 Now the conflict error, look at the transaction start-time, this is before the restart of zope !! 2007-05-31 09:45:25 INFO ZPublisher.Conflict ConflictError at /uniben/campus/students/A923157/study_course/create_level: database conflict error (oid 0x3360e3, class BTrees._OIBTree.OIBucket, serial this txn started with 0x036dfd7c73dfc1dd 2007-05-31 07:24:27.157981, serial currently committed 0x036dfd9131112455 2007-05-31 07:45:11.500069) (1 conflicts (0 unresolved) since startup at Thu May 31 09:44:24 2007) now this is retried for A923157 2007-05-31 09:45:26 INFO Skins.create_level A923157 started to create level 200 2007-05-31 09:45:45 INFO Skins.create_level A923157 finished to create level 200 -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
[ZODB-Dev] Re: [Zope-dev] Re: [Bug] ZODB invalidation processing
Joachim Schmitz schrieb: I could reproduce the conflict error on my local machine not using ZEO. I invoked the longrunning process create_level for two users after a zope-restart. here is the log: 2007-05-31 09:44:24 INFO Zope Ready to handle requests 2007-05-31 09:44:39 INFO Skins.create_level A923157 started to create level 200 2007-05-31 09:44:41 INFO Skins.create_level Y617041 started to create level 400 the next two entries are printed before the redirect/commit 2007-05-31 09:45:01 INFO Skins.create_level Y617041 finished to create level 400 2007-05-31 09:45:06 INFO Skins.create_level A923157 finished to create level 200 Now the conflict error, look at the transaction start-time, this is before the restart of zope !! 2007-05-31 09:45:25 INFO ZPublisher.Conflict ConflictError at /uniben/campus/students/A923157/study_course/create_level: database conflict error (oid 0x3360e3, class BTrees._OIBTree.OIBucket, serial this txn started with 0x036dfd7c73dfc1dd 2007-05-31 07:24:27.157981, serial currently committed 0x036dfd9131112455 2007-05-31 07:45:11.500069) (1 conflicts (0 unresolved) since startup at Thu May 31 09:44:24 2007) now this is retried for A923157 2007-05-31 09:45:26 INFO Skins.create_level A923157 started to create level 200 2007-05-31 09:45:45 INFO Skins.create_level A923157 finished to create level 200 I deleted the created objects and repeated the test: 2007-05-31 12:46:12 ERROR Zope.ZCatalog uncatalogObject unsuccessfully attempted to uncatalog an object with a uid of /uniben/campus/students/A923157/study_course/200/ZOO213. 2007-05-31 12:47:05 INFO Skins.create_level Y617041 started to create level 400 2007-05-31 12:47:14 INFO Skins.create_level A923157 started to create level 200 2007-05-31 12:47:25 INFO Skins.create_level Y617041 finished to create level 400 2007-05-31 12:47:40 INFO Skins.create_level A923157 finished to create level 200 2007-05-31 12:47:58 INFO ZPublisher.Conflict ConflictError at /uniben/campus/students/A923157/study_course/create_level: database conflict error (oid 0x3647b0, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036dfe463486d955 2007-05-31 10:46:12.310958, serial currently committed 0x036dfe479a5725cc 2007-05-31 10:47:36.173536) (3 conflicts (0 unresolved) since startup at Thu May 31 09:44:24 2007) again the txn starttime is that of an older transaction, and it is the time of the uncatalog entry. If I invoke the create_level only for one student, no conflict-error occurs. -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
[ZODB-Dev] Re: [Zope-dev] Re: [Bug] ZODB invalidation processing
Hi, I was able to locate the places in the Zope-sources where the conflict error is triggered. On my local system it's in ZODB.FileStorage in the store-method there is if serial != cached_tid: rdata = self.tryToResolveConflict(oid, cached_tid,serial, data) in the tryToResolveConflict method of ZODB.ConnflictResolution there is: committed = state(self, oid, committedSerial, prfactory, committedData) print resolve, resolve resolved = resolve(old, committed, newstate) I found that the resolve-function raises an ConflictError exception, so I put an print there to find out which resolve function. Here is the output: resolve bound method Length._p_resolveConflict of BTrees.Length.Length object at 0xb28fff6c resolve built-in method _p_resolveConflict of BTrees._OIBTree.OIBucket object at 0xb1b81224 resolve built-in method _p_resolveConflict of BTrees._OIBTree.OIBucket object at 0xb1b81224 resolve built-in method _p_resolveConflict of BTrees._OIBTree.OIBucket object at 0xb260c80c resolve built-in method _p_resolveConflict of BTrees._OIBTree.OIBucket object at 0xb260c614 resolve bound method Length._p_resolveConflict of BTrees.Length.Length object at 0xb2a9146c resolve built-in method _p_resolveConflict of BTrees._IOBTree.IOBucket object at 0xb1b81224 The last resolve raises an exeption (Pdb) p sys.exc_info() (class ZODB.POSException.BTreesConflictError at 0xb78df0bc, BTreesConflictError(-1, 47, 47, 6), traceback object at 0xb1c34dec) How can I invest this further, especially how can I get information about the actual object,which is causing the conflict. -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
[ZODB-Dev] Re: [Bug] ZODB invalidation processing
Hi Dieter, thanks for this hint. Dieter Maurer schrieb: Perry wrote at 2007-5-25 13:16 +0200: database conflict error (oid 0x7905e6, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036ddc2a44454dee 2007-05-25 09:14:16.000950, serial currently committed 0x036ddc2c21950377 2007-05-25 09:16:07.870801) (80 conflicts (10 unresolved) since startup at Fri May 25 05:19:08 2007) In our private Zope version, I have still a note like this: # DM 2005-08-22: always call '_flush_invalidations' as it does # more than cache handling only self._flush_invalidations() if self._reset_counter != global_reset_counter: # New code is in place. Start a new cache. self._resetCache() # DM 2005-08-22: always call '_flush_invalidations' ##else: ##self._flush_invalidations() The note indicates that the bug was fixed at least at 2005-08-22 (though the handling was not completely right in case the cache was reset). In ZODB.Connection.Connection.open I see: if self._reset_counter != global_reset_counter: # New code is in place. Start a new cache. self._resetCache() else: self._flush_invalidations() So self._flush_invalidations() is only called in the else-condition. In your patch it is always called. I try your version and report back. -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
Re: [ZODB-Dev] Re: [Bug] ZODB invalidation processing
Joachim Schmitz schrieb: Hi Dieter, thanks for this hint. Dieter Maurer schrieb: Perry wrote at 2007-5-25 13:16 +0200: database conflict error (oid 0x7905e6, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036ddc2a44454dee 2007-05-25 09:14:16.000950, serial currently committed 0x036ddc2c21950377 2007-05-25 09:16:07.870801) (80 conflicts (10 unresolved) since startup at Fri May 25 05:19:08 2007) In our private Zope version, I have still a note like this: # DM 2005-08-22: always call '_flush_invalidations' as it does # more than cache handling only self._flush_invalidations() if self._reset_counter != global_reset_counter: # New code is in place. Start a new cache. self._resetCache() # DM 2005-08-22: always call '_flush_invalidations' ##else: ##self._flush_invalidations() The note indicates that the bug was fixed at least at 2005-08-22 (though the handling was not completely right in case the cache was reset). In ZODB.Connection.Connection.open I see: if self._reset_counter != global_reset_counter: # New code is in place. Start a new cache. self._resetCache() else: self._flush_invalidations() So self._flush_invalidations() is only called in the else-condition. In your patch it is always called. I try your version and report back. I patched the ZODB to always do the self._flush_invalidations(). But that didn't change anything, and after looking at the code it couldn't cause it was already always called. here again is the history of a conflict error for one user which finally fails: 2007-05-28T18:32:12 INFO ZPublisher.Conflict ConflictError at /VirtualHostBase/http/uniben.waeup.org:80/uniben/VirtualHostRoot/campus/students/V659242/study_course/create_level: database conflict error (oid 0x7fd771, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036deefb352fd600 2007-05-28 17:31:12.465670, serial currently committed 0x036deefb9aa4d733 2007-05-28 17:31:36.244666) (34 conflicts (4 unresolved) since startup at Mon May 28 17:41:55 2007) 2007-05-28T18:32:44 INFO ZPublisher.Conflict ConflictError at /VirtualHostBase/http/uniben.waeup.org:80/uniben/VirtualHostRoot/campus/students/V659242/study_course/create_level: database conflict error (oid 0x7fd771, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036deefb9aa4d733 2007-05-28 17:31:36.244666, serial currently committed 0x036deefc2e4ff122 2007-05-28 17:32:10.854439) (35 conflicts (4 unresolved) since startup at Mon May 28 17:41:55 2007) 2007-05-28T18:33:15 INFO Skins.create_level V659242 finished to create level 1002007-05-28T18:34:29 INFO ZPublisher.Conflict ConflictError at /VirtualHostBase/http/uniben.waeup.org:80/uniben/VirtualHostRoot/campus/students/V659242/study_course/create_level: database conflict error (oid 0x7fd771, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036deefc2e4ff122 2007-05-28 17:32:10.854439, serial currently committed 0x036deefe18489244 2007-05-28 17:34:05.691441) (36 conflicts (4 unresolved) since startup at Mon May 28 17:41:55 2007) 2007-05-28T18:35:21 INFO Skins.create_level V659242 finished to create level 1002007-05-28T18:38:36 INFO ZPublisher.Conflict ConflictError at /VirtualHostBase/http/uniben.waeup.org:80/uniben/VirtualHostRoot/campus/students/V659242/study_course/create_level: database conflict error (oid 0x7fd771, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036deefe18489244 2007-05-28 17:34:05.691441, serial currently committed 0x036def009207e011 2007-05-28 17:36:34.225960) (42 conflicts (4 unresolved) since startup at Mon May 28 17:41:55 2007) -- 2007-05-28T18:38:36 ERROR Zope.SiteErrorLog http://uniben.waeup.org/campus/students/V659242/study_course/create_level Traceback (innermost last): Module Zope2.App.startup, line 173, in zpublisher_exception_hook Module ZPublisher.Publish, line 121, in publish Module Zope2.App.startup, line 240, in commit Module transaction._manager, line 96, in commit Module Products.CPSCompat.PatchZODBTransaction, line 175, in commit Module transaction._transaction, line 436, in _commitResources Module ZODB.Connection, line 665, in tpc_vote Module ZEO.ClientStorage, line 893, in tpc_vote Module ZEO.ClientStorage, line 877, in _check_serials ConflictError: database conflict error (oid 0x7fd771, class BTrees._IOBTree.IOBucket, serial this txn started with 0x036deefe18489244 2007-05-28 17:34:05.691441, serial currently committed 0x036def009207e011 2007-05-28 17:36:34.225960) -- How can I find out, which objects are really involved in the conflict. -- Gruß Joachim ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
Re: [ZODB-Dev] Re: Mirrored ZODBs
Roché Compaan schrieb: If you have common add/edit methods in your app used by all of your classes, you could do application level replication between Zopes. We have written a small replication module for on of our apps that copes extremely well with disconnected Zopes, and replicates a very compact serialisation of commands to each other (as opposed to whole objects). And they replicate both ways. We been using it for about 4 years in production now. I could send you an example if you want to evaluate this route. could you post it to the list, cause that would be very interesting for us too. -- Mit freundlichen GrüßenJoachim Schmitz .. AixtraWare eK ..Joachim Schmitz ..www.aixtraware.de ..t: +49-2464-8851 Hüsgenstr. 33a .d-52457 Aldenhoven .f: +49-2464-905163 ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org http://mail.zope.org/mailman/listinfo/zodb-dev
