Seemingly inconsistent results with transaction isolation

[Russ]

I was getting some strange transaction isolation behavior with
SQLAlchemy (0.7.2), psycopg2 (2.4.2), and PostgreSQL 8.4. In order to
investigate I wrote up a usage sequence that does this:

1. starts a transaction with a session (s1)
2. starts another transaction with session (s2)
3. updates a value in s1 and commits it
4. reads the value back in s2 using the ORM...
- and it does not get the updated value, although with READ COMMITED
it should
5. reads the value back in s2 using a direct s2.execute statement...
- and it DOES get the updated value (??)

I don't understand why the ORM-triggered read (which does emit SQL) is
not getting the update value, but the direct statement is getting the
update.

When the logger emits SQL I thought it always sent the SQL to the
database. Is this a correct assumption?

Here is my complete (and somewhat verbose) test code that shows the
behaviour...
http://static.inky.ws/syn/325

The postgres engine string obviously needs to be changed
appropriately. And WATCH OUT for the drop tables code in there for
anyone who tries this, if nutty enough to point at a live database.

What is going on? I expect/hope it is something dumb on my end, but I
just don't see it.

Thanks!

[Michael Bayer]

On Sep 9, 2011, at 12:57 AM, Russ wrote:

> I was getting some strange transaction isolation behavior with
> SQLAlchemy (0.7.2), psycopg2 (2.4.2), and PostgreSQL 8.4. In order to
> investigate I wrote up a usage sequence that does this:
>
> 1. starts a transaction with a session (s1)
> 2. starts another transaction with session (s2)
> 3. updates a value in s1 and commits it
> 4. reads the value back in s2 using the ORM...
> - and it does not get the updated value, although with READ COMMITED
> it should
> 5. reads the value back in s2 using a direct s2.execute statement...
> - and it DOES get the updated value (??)
>
> I don't understand why the ORM-triggered read (which does emit SQL) is
> not getting the update value, but the direct statement is getting the
> update.
>
> When the logger emits SQL I thought it always sent the SQL to the
> database. Is this a correct assumption?
>
> Here is my complete (and somewhat verbose) test code that shows the
> behaviour...
> http://static.inky.ws/syn/325

Thanks for the clear example case. So yeah this is basic identity map stuff. On line 88, "s2c1 =", you'll find that the s2c1 you are getting there is the same object as the one you loaded on line 77:

s2c1_a = s2.query(Counter).filter_by(name = "C1").one()
assert s2c1 is s2c1_a

So suppose you're in a series of steps, and you loaded s2c1, and then as a matter of course you looked at s2c1.count, saw that it was "1", then continued doing things based on that assumption. If a concurrent transaction were to come in from underneath and change "1" to "222" while you were still in your ongoing operation, you might be pretty upset (in this case you wouldn't be, but consider the implications if it were across the board...especially on a non-isolated system like MySQL).

It's only at commit() time that information like this is reconciled, and from there it flows that the ORM, since it is just a Python library, keeps things simple and behaves as though transactions are perfectly isolated, and this means that no unexpired state on any object is overwritten.

The mapped attributes can't reasonably behave as "pure" proxies to the absolute state of a row in the database at all times - it wouldn't be feasible to emit SELECT statements on every access or otherwise do some kind of "live cursors everywhere" approach. In the absence of that, SQLAlchemy can never really know if a concurrent, less than purely isolated transaction has done something to that attribute which may be visible in the current transaction. So we demarcate the point of transaction end, that is commit() or rollback(), as the point when everything is expired unconditionally, and we are again willing to "look" at what's changed.

This should not be construed to mean that you should only use the ORM with SERIALIZABLE isolation. It's instead just something to be aware of. You can of course expire any object or individual attribute at any time. In this case, if you were to add s2.expire(s2c1) on line 88, you'd then get the "222" value on the next check as it would emit a SELECT.

>
> The postgres engine string obviously needs to be changed
> appropriately. And WATCH OUT for the drop tables code in there for
> anyone who tries this, if nutty enough to point at a live database.
>
> What is going on? I expect/hope it is something dumb on my end, but I
> just don't see it.
>
> Thanks!
>

> --
> You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
> To post to this group, send email to sqlal...@googlegroups.com.
> To unsubscribe from this group, send email to sqlalchemy+...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/sqlalchemy?hl=en.
>

[Russ]

Thanks for clarifying with a full answer!

> This should not be construed to mean that you should only use the ORM

> with SERIALIZABLE isolation. It's instead just something to be aware of.

> You can of course expire any object or individual attribute at any time. In

> this case, if you were to add s2.expire(s2c1) on line 88, you'd then get the

> "222" value on the next check as it would emit a SELECT.

But it does seem to emit a select!  The output surrounding the line 88 query is below:

Querying s2 again (whose transaction is still open) to see what it gets for c1...

    SQL >> SELECT counter.id AS counter_id, counter.name AS counter_name, counter.count AS counter_count 

    SQL >> FROM counter 

    SQL >> WHERE counter.name = %(name_1)s

    SQL >> {'name_1': 'C1'}

s2 gets C1.count = 1

... so what were those SQL emmissions about?  They did not seem to arrive at the database (based on the result, anyway).

I had thought it may be identity map stuff, regardless of what SQL I saw being emitted, which is why I tried the direct query in line 96.  The combination of "how the heck did SQLAlchemy know to emit SQL here?" and "ok - SQL was emitted, but why didn't it get the response I expect for READ COMMITTED?" both drove the line 96 check.

Note that if I add the s2.expire(s2c1) before the line 88 query as you suggest, the seemingly emitted SQL output is no different, except that the value actually gets updated:

Querying s2 again (whose transaction is still open) to see what it gets for c1...

    SQL >> SELECT counter.id AS counter_id, counter.name AS counter_name, counter.count AS counter_count 

    SQL >> FROM counter 

    SQL >> WHERE counter.name = %(name_1)s

    SQL >> {'name_1': 'C1'}

s2 gets C1.count = 222

What is happening?  I always trusted the logger output for letting me know when the DB was actually being hit, but now I'm not sure I can.

Thanks,

Russ

[Michael Bayer]

On Sep 9, 2011, at 10:39 AM, Russ wrote:

Thanks for clarifying with a full answer!

> This should not be construed to mean that you should only use the ORM

> with SERIALIZABLE isolation. It's instead just something to be aware of.

> You can of course expire any object or individual attribute at any time. In

> this case, if you were to add s2.expire(s2c1) on line 88, you'd then get the

> "222" value on the next check as it would emit a SELECT.

But it does seem to emit a select!  The output surrounding the line 88 query is below:

Querying s2 again (whose transaction is still open) to see what it gets for c1...

    SQL >> SELECT counter.id AS counter_id, counter.name AS counter_name, counter.count AS counter_count 

    SQL >> FROM counter 

    SQL >> WHERE counter.name = %(name_1)s

    SQL >> {'name_1': 'C1'}

s2 gets C1.count = 1

... so what were those SQL emmissions about?  They did not seem to arrive at the database (based on the result, anyway).

when you say query(Class).filter(<criterion>).one(), that always emits SQL.  It's an open-ended query, and SQLalhcemy doesn't know that s2c1 is the object which corresponds to the SQL you're about to emit.   When the row comes back, it then extracts the primary key from the incoming row, determines that identity is already in the identity map and is unexpired, and the row is skipped (that's the disconnect here - incoming rows are not used if the existing identity exists and is unexpired).

if OTOH you had said query(Class).get(pk), that would pull from the identity map directly and not even hit the DB in this case.

[Russ]

when you say query(Class).filter(<criterion>).one(), that always emits SQL.  It's an open-ended query, and SQLalhcemy doesn't know that s2c1 is the object which corresponds to the SQL you're about to emit.   When the row comes back, it then extracts the primary key from the incoming row, determines that identity is already in the identity map and is unexpired, and the row is skipped

It ignores new data?  I'm clearly going to need to be even more careful about this when I expect 'read committed' behaviour from the database.

 

(that's the disconnect here - incoming rows are not used if the existing identity exists and is unexpired).

Is there a global, or per session or something, way to change this ignore-new-data behavior (aside from manually expiring objects prior to querying for data?).  Or even more brutal, can the identity map feature be turned off altogether on a per session basis?

For those cases when 'read committed' and the associated transaction-transaction contamination is actually the desired behavior, having to manually tell SQLAlchemy to expire everything all the time so that it doesn't ignore new incoming data is quite an extra layer to worry about on top of the the already treacherous concurrency issues around 'read committed'.  I always knew the identity map was something to be wary of with concurrency since it is effectively another layer of isolation on top of what the DB is set up to do, but didn't consider the fact that new data that is read would be ignored.

From earlier you said:

 

If a concurrent transaction were to come in from underneath and change "1" to "222" while you were still in your ongoing operation, you might be pretty upset

But I shouldn't be!  That is exactly how 'read committed' is supposed to behave.  If I don't want that, I should be setting "repeatable read" or "serializable".   Although I guess it's true that most developers don't quite know about transaction isolation levels (I sure didn't until fairly recently) and might be upset with SQLAlchemy at the first layer, if it did happen to them...

if OTOH you had said query(Class).get(pk), that would pull from the identity map directly and not even hit the DB in this case.

I usually end up using one() and never use get()... I'll look at using get() now, as frequently my one() criteria was only on the PK.  And I'll obviously be wary of isolation issues with this.  Usually having the identity map is awesome.

My main issue was/is that I saw SQL being emitted, was expecting 'read committed' behaviour, and didn't get it.  Now I completely know why... thanks again.

Russ

[Michael Bayer]

On Sep 9, 2011, at 5:11 PM, Russ wrote:

when you say query(Class).filter(<criterion>).one(), that always emits SQL.  It's an open-ended query, and SQLalhcemy doesn't know that s2c1 is the object which corresponds to the SQL you're about to emit.   When the row comes back, it then extracts the primary key from the incoming row, determines that identity is already in the identity map and is unexpired, and the row is skipped

It ignores new data?  I'm clearly going to need to be even more careful about this when I expect 'read committed' behaviour from the database.

 

(that's the disconnect here - incoming rows are not used if the existing identity exists and is unexpired).

Is there a global, or per session or something, way to change this ignore-new-data behavior (aside from manually expiring objects prior to querying for data?).  Or even more brutal, can the identity map feature be turned off altogether on a per session basis?

There's a method on query() called populate_existing().  This method was added back in the 0.3 days before we had the model of the "transaction" representing the scope of data, and we hadn't figured out the best boundary upon which data should be expired - people wanted to get at new data and this was what we gave them.    It sets the "overwrite" flag for all rows received.   Every row that comes in matching any existing identity will overwrite the object as if it were freshly loaded.  Note this includes pending changes on the object, so usually autoflushing beforehand is a good idea (i.e. leave autoflush on).   It's likely that this will solve the exact usage you're looking for.

I can sense this whole thing is surprising to you, so I'd ask you consider the rationale behind how this works.    The model is based off of that of other ORMs like Hibernate (they call it the "transaction level cache") and Storm.   It's not trivial to go out and repeatedly fetch new data from the database for a graph of objects currently in memory.  The assumption that the field of objects is "isolated" by default, using manual expiration as a hedge against specific cases where de-isolated communication is desired, is pretty standard.    De-isolated communication between ongoing transactions is not the usual way most data operations proceed.

For those cases when 'read committed' and the associated transaction-transaction contamination is actually the desired behavior, having to manually tell SQLAlchemy to expire everything all the time so that it doesn't ignore new incoming data is quite an extra layer to worry about on top of the the already treacherous concurrency issues around 'read committed'.  I always knew the identity map was something to be wary of with concurrency since it is effectively another layer of isolation on top of what the DB is set up to do, but didn't consider the fact that new data that is read would be ignored.

From earlier you said:

 

If a concurrent transaction were to come in from underneath and change "1" to "222" while you were still in your ongoing operation, you might be pretty upset

But I shouldn't be!  That is exactly how 'read committed' is supposed to behave.

 If I don't want that, I should be setting "repeatable read" or "serializable".   Although I guess it's true that most developers don't quite know about transaction isolation levels (I sure didn't until fairly recently) and might be upset with SQLAlchemy at the first layer, if it did happen to them...

OK but this is the basic notion of "optimistic" concurrency - most applications would *want* transactions to be SERIALIZABLE - that is, I can do anything I want in a transaction and its perfectly isolated.  But then the application performs like crap.   The lowering of concurrency levels is usually a tradeoff we make for performance reasons - not typically as an inter-transaction communication system as you are looking for here (though in some cases, as with counters, yes).    The ORM defaults to the former assumption as the usual way of working.    Features like "version id", a feature we got from Hibernate, exist as a means of optimistic concurrency control - when one wants changes to data to be "isolated", without the expense of locking that SERIALIZABLE incurs.    SERIALIZABLE not only is expensive, it often is not even available such as for an app using MySQL MyISAM tables.   

I'd also wonder if a system that promises "exact mirroring of rows down to the transaction isolation behavior" would need to have completely constant communication with the database for every single operation, down to the access of an individual attribute.   Only refreshing data when the user explicitly emits SELECT might be just as arbitrary as only refreshing data when COMMIT is emitted.      I've always felt that the COMMIT boundary was a great place to do the expiration and in the old days I didn't even want it to do that (most apps are hindered by excessive SELECTs).