[ZODB-Dev] Same transaction object (re)-used for subsequent requests?

[Tim Peters]

[Andreas Jung]
> I encountered the following strange behavior with Zope 2.8.8.

I couldn't find "a problem" in the following.  Are you having a
problem, or just asking a question?

> The following code is used to integrate SQLAlchemy with
> Zope. A registered utility subclassing ZopeBaseWrapper provides
> a 'connection' property. This property should always return
> for a given transaction the same sqlalchemy.Connection object
> (which is like a connection from a connection pool within a DA).
>
> Within a thread-local cache the last id of the transaction and the last
> connection is stored in order to return the connection from the cache if
> the property 'connection' is called/used multiple times within one
> request/one
> transaction.
>
> A ConnectionDataManger instance is added a data manager to the current
> transaction in order to integrate the ZODB transaction with the transaction
> system by SQLAlchemy.
>
>
> class ConnectionDataManager(object):
>     """ Wraps connection into transaction context of Zope """
>
>     implements(IDataManager)
>
>     def __init__(self, connection):
>         self.connection = connection
>         self.transaction = connection.begin()
>
>     def tpc_begin(self, trans):
>         log('tpc_begin() - %s' % trans)
>         pass
>
>     def abort(self, trans):
>         self.transaction.rollback()
>         self.connection.close()
>         self.connection = None
>         log('abort() - %s' % trans)
>
>     def commit(self, trans):
>         self.transaction.commit()
>         log('commit() - %s' % trans)
>         self.connection.close()
>         self.connection = None
>
>     def tpc_vote(self, trans):
>         pass
>
>     def tpc_finish(self, trans):
>         log('tcp_finish() - %s' % trans)
>         pass
>
>     def tpc_abort(self, trans):
>         log('tcp_abort() - %s' % trans)
>         pass
>
>     def sortKey(self):
>         return str(id(self))
>
> _connection_cache = threading.local() # module-level cache
>
> class ZopeBaseWrapper(BaseWrapper):
>
>     @property
>     def connection(self):
>
>         if not hasattr(_connection_cache, 'last_connection'):
>             _connection_cache.last_transaction = None
>             _connection_cache.last_connection = None
>
>         # get current transaction
>         txn = transaction.get()
>         txn_str = str(txn)
>         log('current thread - %s' % threading.currentThread())
>         log('checking for transaction - %s' % txn_str)
>
>         # return cached connection if we are within the same transaction
>         # and same thread
>         if txn_str == _connection_cache.last_transaction:
>             log('returning cached connection - %s' %
> _connection_cache.last_connection)
>             return _connection_cache.last_connection
>
>         # no cached connection, let's create a new one
>         connection = self.engine.connect()
>         log('creating new connection - %s' % connection)
>
>         # register a DataManager with the current transaction
>         txn.join(ConnectionDataManager(connection))
>
>         # update thread-local cache
>         _connection_cache.last_transaction = txn_str
>         _connection_cache.last_connection = connection
>
>         # return the connection
>         return connection
>
> This works almost.

In what specific way (if any) does it /not/ work?

> However when I hammer my Zope instance using ab2
> (without concurrent request, option -c 1) then in some rare cases I see
> that a new request uses a formerly used transaction object. Look at the
> output
>
> Request #1:
> *** <_DummyThread(Dummy-1, started daemon)> - current thread <_DummyThread(Dummy-1, started daemon)>
> *** <_DummyThread(Dummy-1, started daemon)> - checking for transaction - <transaction._transaction.Transaction object at 0x2ba7b29e7050>
> *** <_DummyThread(Dummy-1, started daemon)> - creating new connection - <sqlalchemy.engine.base.Connection object at 0x2ba7b29c4b90>
> *** <_DummyThread(Dummy-1, started daemon)> - tpc_begin() - <transaction._transaction.Transaction object at 0x2ba7b29e7050>
> *** <_DummyThread(Dummy-1, started daemon)> - commit() - <transaction._transaction.Transaction object at 0x2ba7b29e7050>
> *** <_DummyThread(Dummy-1, started daemon)> - tcp_finish() - <transaction._transaction.Transaction object at 0x2ba7b29e7050>
>
> Request #2:
> *** <_DummyThread(Dummy-1, started daemon)> - current thread - <_DummyThread(Dummy-1, started daemon)>
> *** <_DummyThread(Dummy-1, started daemon)> - checking for transaction - <transaction._transaction.Transaction object at 0x2ba7b29e7050>
> *** <_DummyThread(Dummy-1, started daemon)> - returning cached connection -
 <sqlalchemy.engine.base.Connection object at 0x2ba7b29c4b90>
>
> As you can see request #1 commits without a problem.

Are you implying (by silence ;-)) that request #2 does not commit
without problem?


> But for the second request handled by the same thread the same transaction
> object is re-used.
>
> Bug or feature?

There's no way to know from the above whether or not it's "the same
transaction object".  All I can tell from the output is that the
transaction objects (TO) in both blocks of output happen to live at
the same memory address.  That's in fact very likely if the TO from
block #1 is freed and then very quickly a new TO is allocated.
Python's size-segregated small-object allocator deliberately works (up
to a point) like a stack, reusing a chunk of memory ASAP (while it's
most likely to still be high in the OS+HW memory hierarchy).

Here's a very simple example using builtins to illustrate this:

>>> x = {1: 2}
>>> id(x)
10603952
>>> del x
>>> x = {3: 4}
>>> id(x)
10603952

Those are obviously entirely different dictionaries, but they live at
the same memory address (and likely so, by design, and thanks to the
quick memory reuse allowed by refcounting).

In any case, yes, the intent is that a new transaction object is used
for each transaction; but, no, seeing the same memory address does not
mean that isn't happening.