Include both modified and just created objects into invalidations

[navytux]

Starting from 1999 (b3805a2 "just getting started") only modified - not
just created - objects were included into ZEO invalidation messages:

b3805a2f#diff-52fb76aaf08a1643cdb8fdaf69e37802R126-R127

In 2000 this behaviour was further changed to not send invalidation
message at all if the only objects a transaction has were the created ones:

230ffbe8#diff-52fb76aaf08a1643cdb8fdaf69e37802L163-R163

In 2016 the latter was reconsidered as bug and fixed in ZEO5 because
ZODB5 relies more heavily on MVCC semantic and needs to be notified
about every transaction committed to storage to be able to properly
update ZODB.Connection view:

02943acd#diff-52fb76aaf08a1643cdb8fdaf69e37802L889-R834
9613f09b

In 2020, with this patch, I'm proposing to reconsider initial "send only
modified, not created objects" as bug, and include both modified and
just created objects into invalidation messages at least for the
following reasons:

• a ZODB client (not necessarily native ZODB/py client) can maintain
  raw cache for the storage. If such client tries to load an oid at
  database view when that object did not existed yet, gets "no object"
  reply and stores that information into raw cache, to properly invalidate
  the cache it needs an invalidation message from ZODB server that
  includes created object.

• tools like zodb watch [1,2,3] don't work properly (give incorrect output)
  if not all objects modified/created by a transaction are included into
  invalidation messages.

• similarly to zodb watch, a monitoring tool, that would want to be
  notified of all created/modified objects, won't see full
  database-change picture, and so won't work properly without knowing
  which objects were created.

• wendelin.core 2 - which builds data from ZODB BTrees and data objects
  into virtual filesystem - needs to get invalidation messages with both
  modified and created objects to properly implement its own lazy
  invalidation and isolation protocol for file blocks in OS cache: when
  a block of file is accessed, all clients, that have this block mmaped,
  need to be notified and asked to remmap that block into particular
  revision of the file depending on a client's view of the filesystem and
  database [4,5].

  To compute to where a client needs to remmap the block, WCFS server
  (that in turn acts as ZODB client wrt ZEO/NEO server), needs to be able
  to see whether client's view of the filesystem is before object creation
  (and then ask that client to pin that block to hole), or after creation
  (and then ask the client to pin that block to corresponding revision).

  This computation needs ZODB server to send invalidation messages in
  full: with both modified and just created objects.

The patch is simple - it removes if serial != b"\0\0\0\0\0\0\0\0"
before queuing oid into ZEOStorage.invalidated, and adjusts the tests
correspondingly. From my point of view and experience, in practice, this
patch should not cause any compatibility break nor performance regressions.

Thanks beforehand,
Kirill

/cc @jimfulton

[1] https://lab.nexedi.com/kirr/neo/blob/ea53a795/go/zodb/zodbtools/watch.go
[2] https://lab.nexedi.com/kirr/neo/commit/e0d59f5d
[3] https://lab.nexedi.com/kirr/neo/commit/c41c2907

[4] https://lab.nexedi.com/kirr/wendelin.core/blob/1efb5876/wcfs/wcfs.go#L94-182
[5] https://lab.nexedi.com/kirr/wendelin.core/blob/1efb5876/wcfs/client/wcfs.h#L20-71

[navytux]

CI is failing with errors like

821 Failure in test checkTransactionExtensionFromIterator (ZEO.tests.testZEO.FileStorageClientHexTests)
822Traceback (most recent call last):
823  File "/opt/python/2.7.15/lib/python2.7/unittest/case.py", line 329, in run
824    testMethod()
825  File "/home/travis/build/zopefoundation/ZEO/eggs/ZODB-5.6.0-py2.7.egg/ZODB/tests/IteratorStorage.py", line 114, in checkTransactionExtensionFromIterator
826    self.assertNotEqual(extension_bytes, txn.extension_bytes)
827  File "/opt/python/2.7.15/lib/python2.7/unittest/case.py", line 522, in assertNotEqual
828    raise self.failureException(msg)
829AssertionError: '\x80\x03}q\x01U\x03fooK\x01s.' == '\x80\x03}q\x01U\x03fooK\x01s.'

and like

Error in test checkTransactionExtensionFromIterator (ZEO.tests.testZEO.BlobAdaptedFileStorageTests)
738Traceback (most recent call last):
739  File "/opt/python/3.4.8/lib/python3.4/unittest/case.py", line 58, in testPartExecutor
740    yield
741  File "/opt/python/3.4.8/lib/python3.4/unittest/case.py", line 580, in run
742    testMethod()
743  File "/home/travis/build/zopefoundation/ZEO/eggs/ZODB-5.6.0-py3.4.egg/ZODB/tests/IteratorStorage.py", line 101, in checkTransactionExtensionFromIterator
744    revid = self._dostore(oid, data=MinPO(1), extension=ext)
745  File "/home/travis/build/zopefoundation/ZEO/eggs/ZODB-5.6.0-py3.4.egg/ZODB/tests/StorageTestBase.py", line 157, in _dostore
746    r2 = self._storage.tpc_vote(t)
747  File "/home/travis/build/zopefoundation/ZEO/src/ZEO/ClientStorage.py", line 771, in tpc_vote
748    self._check_trans(txn, 'tpc_vote')
749  File "/home/travis/build/zopefoundation/ZEO/src/ZEO/ClientStorage.py", line 489, in _check_trans
750    raise ClientDisconnected(meth, 'on a disconnected transaction')
751ZEO.Exceptions.ClientDisconnected: ('tpc_vote', 'on a disconnected transaction')

That are unrelated to my patch and that were there before with current master.

In my understanding all this errors are caused by ZODB 5.6.0 upgrade, and are likely to go away after #159.

[navytux]

ZEO4 backport: #161.

[jamadden]

Seems reasonable to me.

[navytux]

@jamadden, thanks for feedback. Is it ok to apply the patch to master?

[jamadden]

I would personally prefer to see the changes needed to make the builds green merged, then this rebased on master and merged when it too is green. PR #159 has been approved, it just needs to be merged. It wasn't clear that the author of that PR was satisfied with it though.

[navytux]

Thanks. Ok, let's wait for #159 to be resolved first. /cc @jmuchemb

[navytux]

For the record: the property that all objects - both modified and just created - are included into invalidation messages is required and can help to remove next_serial from loadBefore return. This, in turn, can help to do 2x less SQL queries in loadBefore for RelStorage and NEO (and maybe other storages too): zopefoundation/ZODB#318 (comment).

[navytux]

Corresponding amendment to ZODB interfaces: zopefoundation/ZODB#319.

[navytux]

For the record: the property that all objects - both modified and just created - are included into invalidation messages is required and can help to remove next_serial from loadBefore return. This, in turn, can help to do 2x less SQL queries in loadBefore for RelStorage and NEO (and maybe other storages too): zopefoundation/ZODB#318 (comment).

Patch with loadAt - that amends loadBefore semantic as explained above - is here: zopefoundation/ZODB#323.

[navytux]

( rebased the patch to master after #159 has been merged )

[navytux]

CI is ok besides pypy which failed in zeo-fan-out.test . I'm not sure whether it is related to my patch or not. For the reference: CI fo #159 itself has two failures in py27 and in pypy: https://travis-ci.org/github/zopefoundation/ZEO/builds/711701287.

[dataflake]

CI is ok besides pypy which failed in zeo-fan-out.test . I'm not sure whether it is related to my patch or not. For the reference: CI fo #159 itself has two failures in py27 and in pypy: https://travis-ci.org/github/zopefoundation/ZEO/builds/711701287.

You're pointing to an outdated CI result from #159 that has passing test runs after it, so that specific test result doesn't mean much. The latest test run on your PR succeeds as well.

As I have found working on #159, the tests have timing/race condition issues in at least several places. Tests that fail during one run mysteriously succeed the next time. They're not a reliable problem indicator unless you've run them several times and you start noticing which specific tests tend to fail spuriously so you can distinguish test timing issues versus real issues.

[navytux]

@dataflake, thanks for feedback. Indeed CI on current master is green. CI for my patch, after plain re-upload, is also green now. I've quickly looked into what happens in zeo-fan-out.test, and it looks like the failure there is related to #155 ("Data corruption due to race condition with external invalidations"):

ZEO/src/ZEO/tests/zeo-fan-out.test

Lines 88 to 132 in d535f53

	Now, let's see if we can break it. :)
	>>> def f():
	... c = db1.open(transaction.TransactionManager())
	... r = c.root()
	... i = 0
	... while i < 100:
	... r[1].v -= 1
	... r[2].v += 1
	... try:
	... c.transaction_manager.commit()
	... i += 1
	... except ZODB.POSException.ConflictError:
	... c.transaction_manager.abort()
	... c.close()
	>>> import threading
	>>> threadf = threading.Thread(target=f)
	>>> threadg = threading.Thread(target=f)
	>>> threadf.start()
	>>> threadg.start()
	>>> s2 = db2.storage
	>>> start_time = time.time()
	>>> import os
	>>> from ZEO.ClientStorage import _lock_blob
	>>> while time.time() - start_time < 999:
	... t = tm2.begin()
	... if r2[1].v + r2[2].v:
	... print('oops', r2[1], r2[2])
	... if r2[1].v == 800:
	... break # we caught up
	... path = s2.fshelper.getBlobFilename(*blob_id)
	... if os.path.exists(path):
	... ZODB.blob.remove_committed(path)
	... _ = s2.fshelper.createPathForOID(blob_id[0])
	... blob_lock = _lock_blob(path)
	... s2._call('sendBlob', *blob_id, timeout=9999)
	... blob_lock.close()
	... else: print('Dang')
	>>> threadf.join()
	>>> threadg.join()

It should not be related to my patch, which only extends invalidation messages contents, not change their timings or ordering.

So @jamadden, @jimfulton, everyone, is it ok to merge?

Kirill

P.S. Yes, ZEO5 state seems to be not very good with respect to races...

[jamadden]

LGTM.

[navytux]

@jamadden, thanks, merging.

[navytux]

( changelog entry added in 3de995f )

[navytux]

( hope it is ok )

[jmuchemb]

Note that like NEO, ZEO is now more vulnerable to the memory leak that I tried to fix with zopefoundation/ZODB#185. Even if the leak already existed for ZEO, I mean that the new behaviour increases its probability/severity.

[navytux]

Note that like NEO, ZEO is now more vulnerable to the memory leak that I tried to fix with zopefoundation/ZODB#185. Even if the leak already existed for ZEO, I mean that the new behaviour increases its probability/severity.

@jmuchemb, thanks for the note. It indeed makes more sense to fix the leak by flushing invalidations immediately instead of queuing them indefinitely for closed connections that are kept in DB pool cache. Should we reopen zopefoundation/ZODB#185 to do this?

/cc @jimfulton, @jmadden, @icemac

[jmuchemb]

Should we reopen zopefoundation/ZODB#185 to do this?

It's a PR, not an issue, so no. The suggested implementation is wrong. I will be better to submit a patch in a new PR; actually, I started a draft but it's not finished. Or open an issue, but I don't need it to remember.