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 > [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.
There's really no way to tell what's happening in your app without an example that illustrates the issue, such that if unusual behavior were observed, one could issue a pdb and step around to see the state of things as they progress. You can check the source code of Session.remove() yourself - it issues a close() on the session which detaches all objects, and then the whole thing is just thrown away. Its all Python GC accomplishing the work here, and after remove() nothing on the SQLA side is referencing that Session. Its not just SQLite that would have issues if Session.remove() left connection resources lying around - the connection would still have open transactional resources on it, which would cause locking issues with databases such as Postgresql and MS-SQL. My advice would be, assuming you cannot isolate the issue inside a small test case, to trap the application at the point at which it appears to be opening a "mystery" SessionTransaction, dropping into pdb, and checking around why there's more than one Session in memory, as well as checking what gc.collect() accomplishes here. -- You received this message because you are subscribed to the Google Groups "sqlalchemy" group. To post to this group, send email to sqlalch...@googlegroups.com. To unsubscribe from this group, send email to sqlalchemy+unsubscr...@googlegroups.com. For more options, visit this group at http://groups.google.com/group/sqlalchemy?hl=en.
