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 object at 0x9a3a7a0> checked out from pool [sqlalchemy.pool.SingletonThreadPool.0x...338c:387] DEBUG _ConnectionFairy.checkout: counter = 1 So far, everything is as before. Now, we make additional database calls, exactly as before, to populate the comboboxes. [ersatz.db:904] DEBUG DBMultiSelectField: get_choices: authors Now comes the first unexpected occurrence. The SessionTransaction with id 0x9c814cc referenced below is not the one which was created above, 0x9c8448c. Although there is a logging statement in SessionTransaction.__init__ which produces the logging output indicating an instance was created, this has not happened for ID 0x9c814cc - how/where/why is this SessionTransaction created? SQLA has taken a different path. [sqlalchemy.orm.session:310] DEBUG SessionTransaction._connection_for_bind: not in connections: SessionTransaction/0x9c814cc, Engine(sqlite:////tmp/demo1.db), [] [sqlalchemy.orm.session:323] DEBUG SessionTransaction._connection_for_bind: calling bind.contextual_connect [sqlalchemy.pool.SingletonThreadPool.0x...338c:387] DEBUG _ConnectionFairy.checkout: counter = 2 The existing connection is used but its refcount is bumped up to 2 (reasonably). However, this will cause the connection to not be returned to the pool during cleanup. The remaining combobox-population calls use this connection. [ersatz.db:879] DEBUG DBSelectField: get_choices: publisher [ersatz.db:904] DEBUG DBMultiSelectField: get_choices: tags End of request, and cleanup time: [ersatz.core:747] DEBUG 0.053: time for http://localhost:5000/admin/book/add/ [sqlalchemy.orm.scoping:61] DEBUG ScopedSession.remove registry has, closing: <sqlalchemy.orm.session.Session object at 0x9c841ec> [sqlalchemy.orm.session:762] DEBUG Session.close [sqlalchemy.orm.session:766] DEBUG Session.close: closing transaction: <sqlalchemy.orm.session.SessionTransaction object at 0x9c8448c> [sqlalchemy.pool.SingletonThreadPool.0x...338c:432] DEBUG _ConnectionFairy.close: counter = 2 As a result of the counter not becoming zero when decremented, the connection is not returned to the pool, even though it should be. Is this a bug, or is there some explanation which escapes me? This doesn't appear to be related to the connection being to a SQLite database. Regards, Vinay Sajip [1] http://groups.google.com/group/sqlalchemy/browse_frm/thread/5e08e49fa1722f91 -- You received this message because you are subscribed to the Google Groups "sqlalchemy" group. To post to this group, send email to [email protected]. To unsubscribe from this group, send email to [email protected]. For more options, visit this group at http://groups.google.com/group/sqlalchemy?hl=en.
