[sqlalchemy] Unexpected SessionTransaction behaviour
I posted earlier[1] about an threading anomaly I am getting relating to SQLite with pooling, and was advised to use NullPool. However, it seems like session.remove() for a scoped session is not always cleaning up things as it should, the problem only showing up with SQLite because of its constraints on threaded usage. So I set up to run under a development server (single threaded) and added some additional logging statements to pool.py, orm/session.py and orm/ scoping.py to try to see what was going on. I have tested with two identical requests to a web app. Processing this request results in a fetch of a User (mapped class) given its ID (stored in an HTTP session), followed by some fetches of data to populate comboboxes in the response. There are only SELECT queries - no INSERT/UPDATE/DELETE queries. For the first request, everything appears to behave as expected. For the second (identical) request, an extra checkout is done and a phantom SessionTransaction appears, which results in the connection not being returned to the pool at the end of the request. I'd be grateful for some pointers to what is happening - is it what would be expected, and why are the two identical requests resulting in different flow through SQLA code? Annotated log output: [ersatz.core:706] DEBUG dispatching request GET http://localhost:5000/admin/book/add/ [ersatz.core:677] DEBUG locales: ['en_GB', 'es_ES'] ... [ersatz.contrib.dbauth:539] DEBUG Querying user via id [sqlalchemy.orm.session:228] DEBUG SessionTransaction.__init__: 0x9bc922c [sqlalchemy.orm.session:310] DEBUG SessionTransaction._connection_for_bind: not in connections: SessionTransaction/0x9bc922c, Engine(sqlite:tmp/demo1.db), [] As you would expect, there's no connection for this request, so one is created, checked out from the pool. Likewise, a SessionTransaction is created. [sqlalchemy.orm.session:323] DEBUG SessionTransaction._connection_for_bind: calling bind.contextual_connect [sqlalchemy.pool.SingletonThreadPool.0x...338c:319] DEBUG _ConnectionFairy.__init__ [sqlalchemy.pool.SingletonThreadPool.0x...338c:275] DEBUG Created new connection sqlite3.Connection object at 0x9a3a7a0 [sqlalchemy.pool.SingletonThreadPool.0x...338c:333] DEBUG Connection sqlite3.Connection object at 0x9a3a7a0 checked out from pool [sqlalchemy.pool.SingletonThreadPool.0x...338c:387] DEBUG _ConnectionFairy.checkout: counter = 1 There follow the calls to populate the comboboxes; presumably the existing connection is used, so we don't see any pool-related logging messages. [ersatz.db:904] DEBUG DBMultiSelectField: get_choices: authors [ersatz.db:879] DEBUG DBSelectField: get_choices: publisher [ersatz.db:904] DEBUG DBMultiSelectField: get_choices: tags The request processing is now complete, and cleanup is done using session.remove(). [ersatz.core:747] DEBUG 0.335: time for http://localhost:5000/admin/book/add/ The scoped session closes the session which is stored in a thread- local: [sqlalchemy.orm.scoping:61] DEBUG ScopedSession.remove registry has, closing: sqlalchemy.orm.session.Session object at 0x9bc908c [sqlalchemy.orm.session:762] DEBUG Session.close Which in turn closes the SessionTransaction object created earlier. [sqlalchemy.orm.session:766] DEBUG Session.close: closing transaction: sqlalchemy.orm.session.SessionTransaction object at 0x9bc922c [sqlalchemy.pool.SingletonThreadPool.0x...338c:432] DEBUG _ConnectionFairy.close: counter = 1 Because the refcount for the connection is 1, an underlying _close is called which returns the connection to the pool. [sqlalchemy.pool.SingletonThreadPool.0x...338c:438] DEBUG _ConnectionFairy._close [sqlalchemy.pool.SingletonThreadPool.0x...338c:283] DEBUG _finalize_fairy: sqlite3.Connection object at 0x9a3a7a0 [sqlalchemy.pool.SingletonThreadPool.0x...338c:304] DEBUG Connection sqlite3.Connection object at 0x9a3a7a0 being returned to pool [sqlalchemy.orm.session:228] DEBUG SessionTransaction.__init__: 0x9c814cc During the request processing above, SQLA behaves in an understandable way. Now for the second request, things don't go the same way, which is the thing that puzzles me. [ersatz.core:706] DEBUG dispatching request GET http://localhost:5000/admin/book/add/ [ersatz.core:677] DEBUG locales: ['en_GB', 'es_ES'] ... [ersatz.contrib.dbauth:539] DEBUG Querying user via id [sqlalchemy.orm.session:228] DEBUG SessionTransaction.__init__: 0x9c8448c [sqlalchemy.orm.session:310] DEBUG SessionTransaction._connection_for_bind: not in connections: SessionTransaction/0x9c8448c, Engine(sqlite:tmp/demo1.db), [] As before, there's no connection yet for this request, so one is created, checked out from the pool. Likewise, a SessionTransaction is created. [sqlalchemy.orm.session:323] DEBUG SessionTransaction._connection_for_bind: calling bind.contextual_connect [sqlalchemy.pool.SingletonThreadPool.0x...338c:319] DEBUG _ConnectionFairy.__init__ [sqlalchemy.pool.SingletonThreadPool.0x...338c:333] DEBUG Connection sqlite3.Connection
Re: [sqlalchemy] Unexpected SessionTransaction behaviour
On Jun 14, 2010, at 9:56 AM, Vinay Sajip wrote: I posted earlier[1] about an threading anomaly I am getting relating to SQLite with pooling, and was advised to use NullPool. However, it seems like session.remove() for a scoped session is not always cleaning up things as it should, the problem only showing up with SQLite because of its constraints on threaded usage. So I set up to run under a development server (single threaded) and added some additional logging statements to pool.py, orm/session.py and orm/ scoping.py to try to see what was going on. I have tested with two identical requests to a web app. Processing this request results in a fetch of a User (mapped class) given its ID (stored in an HTTP session), followed by some fetches of data to populate comboboxes in the response. There are only SELECT queries - no INSERT/UPDATE/DELETE queries. For the first request, everything appears to behave as expected. For the second (identical) request, an extra checkout is done and a phantom SessionTransaction appears, which results in the connection not being returned to the pool at the end of the request. I'd be grateful for some pointers to what is happening - is it what would be expected, and why are the two identical requests resulting in different flow through SQLA code? Annotated log output: [ersatz.core:706] DEBUG dispatching request GET http://localhost:5000/admin/book/add/ [ersatz.core:677] DEBUG locales: ['en_GB', 'es_ES'] ... [ersatz.contrib.dbauth:539] DEBUG Querying user via id [sqlalchemy.orm.session:228] DEBUG SessionTransaction.__init__: 0x9bc922c [sqlalchemy.orm.session:310] DEBUG SessionTransaction._connection_for_bind: not in connections: SessionTransaction/0x9bc922c, Engine(sqlite:tmp/demo1.db), [] As you would expect, there's no connection for this request, so one is created, checked out from the pool. Likewise, a SessionTransaction is created. [sqlalchemy.orm.session:323] DEBUG SessionTransaction._connection_for_bind: calling bind.contextual_connect [sqlalchemy.pool.SingletonThreadPool.0x...338c:319] DEBUG _ConnectionFairy.__init__ [sqlalchemy.pool.SingletonThreadPool.0x...338c:275] DEBUG Created new connection sqlite3.Connection object at 0x9a3a7a0 [sqlalchemy.pool.SingletonThreadPool.0x...338c:333] DEBUG Connection sqlite3.Connection object at 0x9a3a7a0 checked out from pool [sqlalchemy.pool.SingletonThreadPool.0x...338c:387] DEBUG _ConnectionFairy.checkout: counter = 1 There follow the calls to populate the comboboxes; presumably the existing connection is used, so we don't see any pool-related logging messages. [ersatz.db:904] DEBUG DBMultiSelectField: get_choices: authors [ersatz.db:879] DEBUG DBSelectField: get_choices: publisher [ersatz.db:904] DEBUG DBMultiSelectField: get_choices: tags The request processing is now complete, and cleanup is done using session.remove(). [ersatz.core:747] DEBUG 0.335: time for http://localhost:5000/admin/book/add/ The scoped session closes the session which is stored in a thread- local: [sqlalchemy.orm.scoping:61] DEBUG ScopedSession.remove registry has, closing: sqlalchemy.orm.session.Session object at 0x9bc908c [sqlalchemy.orm.session:762] DEBUG Session.close Which in turn closes the SessionTransaction object created earlier. [sqlalchemy.orm.session:766] DEBUG Session.close: closing transaction: sqlalchemy.orm.session.SessionTransaction object at 0x9bc922c [sqlalchemy.pool.SingletonThreadPool.0x...338c:432] DEBUG _ConnectionFairy.close: counter = 1 Because the refcount for the connection is 1, an underlying _close is called which returns the connection to the pool. [sqlalchemy.pool.SingletonThreadPool.0x...338c:438] DEBUG _ConnectionFairy._close [sqlalchemy.pool.SingletonThreadPool.0x...338c:283] DEBUG _finalize_fairy: sqlite3.Connection object at 0x9a3a7a0 [sqlalchemy.pool.SingletonThreadPool.0x...338c:304] DEBUG Connection sqlite3.Connection object at 0x9a3a7a0 being returned to pool [sqlalchemy.orm.session:228] DEBUG SessionTransaction.__init__: 0x9c814cc During the request processing above, SQLA behaves in an understandable way. Now for the second request, things don't go the same way, which is the thing that puzzles me. [ersatz.core:706] DEBUG dispatching request GET http://localhost:5000/admin/book/add/ [ersatz.core:677] DEBUG locales: ['en_GB', 'es_ES'] ... [ersatz.contrib.dbauth:539] DEBUG Querying user via id [sqlalchemy.orm.session:228] DEBUG SessionTransaction.__init__: 0x9c8448c [sqlalchemy.orm.session:310] DEBUG SessionTransaction._connection_for_bind: not in connections: SessionTransaction/0x9c8448c, Engine(sqlite:tmp/demo1.db), [] As before, there's no connection yet for this request, so one is created, checked out from the pool. Likewise, a SessionTransaction is created. [sqlalchemy.orm.session:323] DEBUG SessionTransaction._connection_for_bind: calling bind.contextual_connect
