Re: [sqlalchemy] Session.close() appears to infrequently not expunge all objects
On Thu, Sep 4, 2014 at 5:53 PM, Michael Bayer mike...@zzzcomputing.com
wrote:
The code I say appears to expect the session_id to remain on detached
states in certain situations is that the check in Session._attach checks
not only the session_id but that the referenced session still exists in
_sessions:
if state.session_id and \
state.session_id is not self.hash_key and \
state.session_id in _sessions:
raise sa_exc.InvalidRequestError(
Object '%s' is already attached to session '%s'
(this is '%s') % (orm_util.state_str(state),
state.session_id, self.hash_key))
I am interested in this in the hopes that sheds light on the source of
the intermittent failures.
yeah that code is intended to detect when an object is added to a session
that hasn't been removed from another.
So, is the intent of the 'state.session_id in _sessions clause to handle
the situation where the session is collected while it contains instances?
However, the implementation for session.close() has a direct trace that
leads to the session_id set to None for all objects that are either in
the identity map, or in the _new (pending) collection. There's no
ambiguity there.
I agree, it appears to be pretty clear. However, on the application side I
have log messages indicating I successfully commit() and close() the
session before receiving an error saying an instance is still attached to
it:
2014-08-13 14:14:11 tuk1m1cm1 [debug] [DEBUG] db.py:57 - transaction 8710
started
2014-08-13 14:14:12 tuk1m1cm1 [debug] [DEBUG] db.py:143 - transaction 8710
committed
2014-08-13 14:14:12 tuk1m1cm1 [debug] [DEBUG] db.py:57 - transaction 8719
started
2014-08-13 14:14:13 tuk1m1cm1 [debug] [DEBUG] db.py:140 - transaction 8719
rolled back2014-08-13 14:14:13 tuk1m1cm1 [err] [ERROR] threadutils.py:98 -
Error executing asynchronous operation asynch-op function execute at
0x5e54c08(, {}) : Object 'Account at 0x5d49250' is already attached to
session '8710' (this is '8719') at Traceback (most recent call last):...
transaction refers to a session, the integer is the session.hash_key.
In debugging this I have noticed that after the first session has been
closed() and the initializer has returned the session remains in _sessions.
However, if I call gc.collect() the session is removed, suggesting it just
hasn't been fully cleaned up yet.
that's not really accurate. There's a collection of all the Sessions in
the weak referencing map _sessions, and Python's GC may not in fact remove
those sessions in a deterministic way. But that has no bearing upon
testing objects that have been removed from that session, and therefore
have no session_id, if they belong to that session - their session_id has
been cleared out.
I believe this is relevant because if the session were to be GC'ed the
state.session_id in _sessions would not evaluate to true and the attach
to the session I want would succeed.
Since it takes both the state referencing the session and the session
still existing in _sessions, I can't help but wonder if this is a gc issue.
Unfortunately it is not feasible to add gc.collect() calls in our
production application as it introduces too much overhead.
I will tell you how this *can* happen. If you have a Session, and you put
objects in it, then you *don't* close the session; the session just is
dereferenced, and is garbage collected at some point by the above mentioned
weak dictionary. The objects within that session will *not* have anything
done to their session_id in that case. If a new session is started up,
and it happens to take over the same in-memory ID as the one that was just
GC'ed, it will have the same hash key, and will then exist within
_sessions. Then you move your objects to a third session; they will in
fact have a session_id that is represented in _sessions, albeit against a
different session than they started with, and you get the error.
So if that's the case, then the issue here is the result of objects
belonging to ad-hoc sessions that are not closed() explicitly, then those
objects are shuttled along to another session, while busy thread mechanics
in the background keep creating new sessions that occasionally use the same
session identifier and produce this collision.
There's ways to test for this, like assigning a unique counter to each
Session within an event, like the begin() event, then using the
before_attach event to verify that session_id is None, and if not, take a
peek at that Session and its counter, compare it to something on the state.
I believe I have ruled this out with the transaction XXX
started/committed logging I added since I do not see hash keys being
reused.
--
You received this message because you are subscribed to the Google Groups
sqlalchemy group.
To unsubscribe from this group and stop receiving
Re: [sqlalchemy] Session.close() appears to infrequently not expunge all objects
On Sep 5, 2014, at 12:03 PM, Lonnie Hutchinson lonn...@skytap.com wrote:
On Thu, Sep 4, 2014 at 5:53 PM, Michael Bayermike...@zzzcomputing.com wrote:
The code I say appears to expect the session_id to remain on detached
states in certain situations is that the check in Session._attach checks
not only the session_id but that the referenced session still exists in
_sessions:
if state.session_id and \
state.session_id is not self.hash_key and \
state.session_id in _sessions:
raise sa_exc.InvalidRequestError(
Object '%s' is already attached to session '%s'
(this is '%s') % (orm_util.state_str(state),
state.session_id, self.hash_key))
I am interested in this in the hopes that sheds light on the source of the
intermittent failures.
yeah that code is intended to detect when an object is added to a session
that hasn't been removed from another.
So, is the intent of the 'state.session_id in _sessions clause to handle the
situation where the session is collected while it contains instances?
it's to handle the case where Session A was garbage collected, not cleanly
closed, and now an object from that now-gone session wants to be added to a
different session.this might not even be a case we should be handling,
perhaps if we changed the scheme for sessions to be an absolutely unique
counter and just made it more strict. Not a change planned for now though...
I agree, it appears to be pretty clear. However, on the application side I
have log messages indicating I successfully commit() and close() the session
before receiving an error saying an instance is still attached to it:
2014-08-13 14:14:11 tuk1m1cm1 [debug] [DEBUG] db.py:57 - transaction 8710
started
2014-08-13 14:14:12 tuk1m1cm1 [debug] [DEBUG] db.py:143 - transaction 8710
committed
2014-08-13 14:14:12 tuk1m1cm1 [debug] [DEBUG] db.py:57 - transaction 8719
started
2014-08-13 14:14:13 tuk1m1cm1 [debug] [DEBUG] db.py:140 - transaction 8719
rolled back2014-08-13 14:14:13 tuk1m1cm1 [err] [ERROR] threadutils.py:98 -
Error executing asynchronous operation asynch-op function execute at
0x5e54c08(, {}) : Object 'Account at 0x5d49250' is already attached to
session '8710' (this is '8719') at Traceback (most recent call last):..
Again I see lots terms here threadutils, async operations, things that
suggest the application has a complex system of concurrency which may be
misbehaving. I think you should be adding more assertions to your code to
ensure that close() has completed fully before an object is attempted to be
moved to another session.
transaction refers to a session, the integer is the session.hash_key.
In debugging this I have noticed that after the first session has been
closed() and the initializer has returned the session remains in _sessions.
However, if I call gc.collect() the session is removed, suggesting it just
hasn't been fully cleaned up yet.
that's not really accurate. There's a collection of all the Sessions in the
weak referencing map _sessions, and Python's GC may not in fact remove those
sessions in a deterministic way. But that has no bearing upon testing
objects that have been removed from that session, and therefore have no
session_id, if they belong to that session - their session_id has been
cleared out.
I believe this is relevant because if the session were to be GC'ed the
state.session_id in _sessions would not evaluate to true and the attach to
the session I want would succeed.
This is essentially saying that a certain assertion being removed allows the
code to work. But the assertion here is testing for a specific thing; that
an object was not fully detached from a session before it is attempted to be
used in another. I don't see any indication that this assertion is
malfunctioning.
--
You received this message because you are subscribed to the Google Groups
sqlalchemy group.
To unsubscribe from this group and stop receiving emails from it, send an email
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at http://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.
Re: [sqlalchemy] Session.close() appears to infrequently not expunge all objects
Here is the basic outline of the web request hander. It creates an
operation, gets the return value, and either spawns a thread to execute the
operation (with non-sqlalchemy related instrumentation) or completes the
execution on the operation model. In the case I see there is a provisioning
phase and the operation return value is None.
There are two potential threading problems I see:
1) Since op._operation is an ORM, could evaluating it in a boolean context
cause the ORM to be reattached to a previously closed session?
2) if the operation returns orms they will may accessed concurrently by the
handler thread and the execute thread. This return value is sent as the
xmlrpc response and contains only python primitives. The operations we see
this on return None.
try:
op = Operation(..) # the first session is created, used, and closed
here...the close happens in a try/finally and the transaction XXX
committed logging happens after close() completes successfully
ret = op.get_return_value() # the operation invariably returns None in
the vast majority of cases we've seen
if has_attr(op, 'provision'): # the operations we see this with do have
a provision() method
AsyncOperation(LOGGER,
MonitoringAgent.getInstance().monitor(%s-execute %
op.api_name())(_async_execution_logger(op.api_name())(op.execute))) #
execute exists on Operation base class and calls provision
finally:
if op._operation and not op.has_provisioning_phase: # changing the order
of this could avoid boolean evaluation of op._operation in the case we
spawned a thread
op._operation.execution_complete()# does not
get called in the operations we see this error in
On Fri, Sep 5, 2014 at 9:21 AM, Michael Bayer mike...@zzzcomputing.com
wrote:
On Sep 5, 2014, at 12:03 PM, Lonnie Hutchinson lonn...@skytap.com wrote:
On Thu, Sep 4, 2014 at 5:53 PM, Michael Bayermike...@zzzcomputing.com
wrote:
The code I say appears to expect the session_id to remain on detached
states in certain situations is that the check in Session._attach checks
not only the session_id but that the referenced session still exists in
_sessions:
if state.session_id and \
state.session_id is not self.hash_key and \
state.session_id in _sessions:
raise sa_exc.InvalidRequestError(
Object '%s' is already attached to session '%s'
(this is '%s') % (orm_util.state_str(state),
state.session_id, self.hash_key))
I am interested in this in the hopes that sheds light on the source of
the intermittent failures.
yeah that code is intended to detect when an object is added to a session
that hasn't been removed from another.
So, is the intent of the 'state.session_id in _sessions clause to handle
the situation where the session is collected while it contains instances?
it’s to handle the case where Session A was garbage collected, not cleanly
closed, and now an object from that now-gone session wants to be added to a
different session.this might not even be a case we should be handling,
perhaps if we changed the scheme for sessions to be an absolutely unique
counter and just made it more strict. Not a change planned for now
though...
I agree, it appears to be pretty clear. However, on the application side
I have log messages indicating I successfully commit() and close() the
session before receiving an error saying an instance is still attached to
it:
2014-08-13 14:14:11 tuk1m1cm1 [debug] [DEBUG] db.py:57 - transaction 8710
started
2014-08-13 14:14:12 tuk1m1cm1 [debug] [DEBUG] db.py:143 - transaction 8710
committed
2014-08-13 14:14:12 tuk1m1cm1 [debug] [DEBUG] db.py:57 - transaction 8719
started
2014-08-13 14:14:13 tuk1m1cm1 [debug] [DEBUG] db.py:140 - transaction 8719
rolled back2014-08-13 14:14:13 tuk1m1cm1 [err] [ERROR] threadutils.py:98 -
Error executing asynchronous operation asynch-op function execute at
0x5e54c08(, {}) : Object 'Account at 0x5d49250' is already attached to
session '8710' (this is '8719') at Traceback (most recent call last):..
Again I see lots terms here “threadutils”, “async operations”, things that
suggest the application has a complex system of concurrency which may be
misbehaving. I think you should be adding more assertions to your code to
ensure that close() has completed fully before an object is attempted to be
moved to another session.
transaction refers to a session, the integer is the session.hash_key.
In debugging this I have noticed that after the first session has been
closed() and the initializer has returned the session remains in _sessions.
However, if I call gc.collect() the session is removed, suggesting it just
hasn't been fully cleaned up yet.
that's not really accurate. There's a collection of all the Sessions in
the weak referencing map _sessions, and Python's GC may not in fact remove
Re: [sqlalchemy] Session.close() appears to infrequently not expunge all objects
On Sep 4, 2014, at 5:00 PM, Lonnie Hutchinson lonn...@skytap.com wrote: I am using sqlalchemy 0.8.5 with mysql 5.5 and think an intermittent failure I am seeing may be due to an issue in sqlalchemy. Very infrequently I receive an error from Session.add() stating the instance is already attached to session 'XXX' (this is 'YYY') (see below for stack trace). I understand the typical reason this error is raised, but I do not believe the instance should still be attached to XXX, even though it was shortly before (milliseconds) since Session.close() was called on the session. OK I'm seeing some red flags here. I see the word intermittent, which almost always means, multiple threads. Then I see the word, milliseconds. Are we using threads? Are we trying to time things? Because looking at 0.8.5, when you call close(), the objects in that Session are absolutely de-assocaited with that Session, including that session_id is set to None. This is very simple to confirm: from sqlalchemy import * from sqlalchemy.orm import * from sqlalchemy.ext.declarative import declarative_base Base = declarative_base() class A(Base): __tablename__ = 'a' id = Column(Integer, primary_key=True) e = create_engine(sqlite://, echo=True) Base.metadata.create_all(e) sess = Session(e) a1 = A() sess.add(a1) sess.commit() assert a1._sa_instance_state.session_id == sess.hash_key sess.close() assert a1._sa_instance_state.session_id is None there's no milliseconds here. close() completes, and that id is gone. If you are playing with threads, the only way to guarantee one thread finishes something before the other starts is to either join() that thread or use mutexes. My understanding of Session.close() is that upon return all instances should be detached from the session and their instance state session_id attribute should no longer reference the session. This does not appear to be happening since adding the instance to a different session fails since the instance is still attached to the previous session. Above I illustrate that this is not the case. The code path is clear: session.py - line 942 - close() calls: session.py - line 952 - self.expunge_all() session.py - line 965 calls state._detach() on everything in identity + _new. (question. are you trying to move an object that was deleted? that might have issues, but that's not a valid use case). state.py - line 166 - _detach() calls: state.py - line 167: self.session_id = self._strong_obj = None In reading the code it appears as though it is expected in certain situations for the session_id to continue to refer to the session after close since the check for already attached checks session_id as well as whether the session remains in the sessions registry. I'm not seeing that in 0.8.5 at all.what line of code are you referring to ? -- You received this message because you are subscribed to the Google Groups sqlalchemy group. To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+unsubscr...@googlegroups.com. To post to this group, send email to sqlalchemy@googlegroups.com. Visit this group at http://groups.google.com/group/sqlalchemy. For more options, visit https://groups.google.com/d/optout.
Re: [sqlalchemy] Session.close() appears to infrequently not expunge all objects
The session executes in one of many web-server threads, but there is no multi-threading with respect to the session or the objects. The session that was closed is within an initializer and upon return a method on the object is executed that creates a new session and tries to attach objects retrieved from the first session. This method does spawn threads but the exception happens before any threads are spawned. The thread target does not take objects, only python strings. only identifiers used in new sessions to query the objects again. The milliseconds I referred to are between the close() of the first session and the add() that fails in the second session. The code I say appears to expect the session_id to remain on detached states in certain situations is that the check in Session._attach checks not only the session_id but that the referenced session still exists in _sessions: if state.session_id and \ state.session_id is not self.hash_key and \ state.session_id in _sessions: raise sa_exc.InvalidRequestError( Object '%s' is already attached to session '%s' (this is '%s') % (orm_util.state_str(state), state.session_id, self.hash_key)) I am interested in this in the hopes that sheds light on the source of the intermittent failures. In debugging this I have noticed that after the first session has been closed() and the initializer has returned the session remains in _sessions. However, if I call gc.collect() the session is removed, suggesting it just hasn't been fully cleaned up yet. Since it takes both the state referencing the session and the session still existing in _sessions, I can't help but wonder if this is a gc issue. Unfortunately it is not feasible to add gc.collect() calls in our production application as it introduces too much overhead. On Thu, Sep 4, 2014 at 3:20 PM, Michael Bayer mike...@zzzcomputing.com wrote: On Sep 4, 2014, at 5:00 PM, Lonnie Hutchinson lonn...@skytap.com wrote: I am using sqlalchemy 0.8.5 with mysql 5.5 and think an intermittent failure I am seeing may be due to an issue in sqlalchemy. Very infrequently I receive an error from Session.add() stating the instance is already attached to session 'XXX' (this is 'YYY') (see below for stack trace). I understand the typical reason this error is raised, but I do not believe the instance should still be attached to XXX, even though it was shortly before (milliseconds) since Session.close() was called on the session. OK I'm seeing some red flags here. I see the word intermittent, which almost always means, multiple threads. Then I see the word, milliseconds. Are we using threads? Are we trying to time things? Because looking at 0.8.5, when you call close(), the objects in that Session are absolutely de-assocaited with that Session, including that session_id is set to None. This is very simple to confirm: from sqlalchemy import * from sqlalchemy.orm import * from sqlalchemy.ext.declarative import declarative_base Base = declarative_base() class A(Base): __tablename__ = 'a' id = Column(Integer, primary_key=True) e = create_engine(sqlite://, echo=True) Base.metadata.create_all(e) sess = Session(e) a1 = A() sess.add(a1) sess.commit() assert a1._sa_instance_state.session_id == sess.hash_key sess.close() assert a1._sa_instance_state.session_id is None there's no milliseconds here. close() completes, and that id is gone. If you are playing with threads, the only way to guarantee one thread finishes something before the other starts is to either join() that thread or use mutexes. My understanding of Session.close() is that upon return all instances should be detached from the session and their instance state session_id attribute should no longer reference the session. This does not appear to be happening since adding the instance to a different session fails since the instance is still attached to the previous session. Above I illustrate that this is not the case. The code path is clear: session.py - line 942 - close() calls: session.py - line 952 - self.expunge_all() session.py - line 965 calls state._detach() on everything in identity + _new. (question. are you trying to move an object that was deleted? that might have issues, but that's not a valid use case). state.py - line 166 - _detach() calls: state.py - line 167: self.session_id = self._strong_obj = None In reading the code it appears as though it is expected in certain situations for the session_id to continue to refer to the session after close since the check for already attached checks session_id as well as whether the session remains in the sessions registry. I'm not seeing that in 0.8.5 at all.what line of code are you referring to ? -- You received this message because you are subscribed to the Google Groups sqlalchemy group. To
Re: [sqlalchemy] Session.close() appears to infrequently not expunge all objects
On Sep 4, 2014, at 8:17 PM, Lonnie Hutchinson lonn...@skytap.com wrote: The session executes in one of many web-server threads, but there is no multi-threading with respect to the session or the objects. The session that was closed is within an initializer and upon return a method on the object is executed that creates a new session and tries to attach objects retrieved from the first session. This method does spawn threads but the exception happens before any threads are spawned. The thread target does not take objects, only python strings. only identifiers used in new sessions to query the objects again. The milliseconds I referred to are between the close() of the first session and the add() that fails in the second session. The code I say appears to expect the session_id to remain on detached states in certain situations is that the check in Session._attach checks not only the session_id but that the referenced session still exists in _sessions: if state.session_id and \ state.session_id is not self.hash_key and \ state.session_id in _sessions: raise sa_exc.InvalidRequestError( Object '%s' is already attached to session '%s' (this is '%s') % (orm_util.state_str(state), state.session_id, self.hash_key)) I am interested in this in the hopes that sheds light on the source of the intermittent failures. yeah that code is intended to detect when an object is added to a session that hasn't been removed from another. However, the implementation for session.close() has a direct trace that leads to the session_id set to None for all objects that are either in the identity map, or in the _new (pending) collection. There's no ambiguity there. In debugging this I have noticed that after the first session has been closed() and the initializer has returned the session remains in _sessions. However, if I call gc.collect() the session is removed, suggesting it just hasn't been fully cleaned up yet. that's not really accurate. There's a collection of all the Sessions in the weak referencing map _sessions, and Python's GC may not in fact remove those sessions in a deterministic way. But that has no bearing upon testing objects that have been removed from that session, and therefore have no session_id, if they belong to that session - their session_id has been cleared out. Since it takes both the state referencing the session and the session still existing in _sessions, I can't help but wonder if this is a gc issue. Unfortunately it is not feasible to add gc.collect() calls in our production application as it introduces too much overhead. I will tell you how this *can* happen. If you have a Session, and you put objects in it, then you *don't* close the session; the session just is dereferenced, and is garbage collected at some point by the above mentioned weak dictionary. The objects within that session will *not* have anything done to their session_id in that case. If a new session is started up, and it happens to take over the same in-memory ID as the one that was just GC'ed, it will have the same hash key, and will then exist within _sessions. Then you move your objects to a third session; they will in fact have a session_id that is represented in _sessions, albeit against a different session than they started with, and you get the error. So if that's the case, then the issue here is the result of objects belonging to ad-hoc sessions that are not closed() explicitly, then those objects are shuttled along to another session, while busy thread mechanics in the background keep creating new sessions that occasionally use the same session identifier and produce this collision. There's ways to test for this, like assigning a unique counter to each Session within an event, like the begin() event, then using the before_attach event to verify that session_id is None, and if not, take a peek at that Session and its counter, compare it to something on the state. -- You received this message because you are subscribed to the Google Groups sqlalchemy group. To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+unsubscr...@googlegroups.com. To post to this group, send email to sqlalchemy@googlegroups.com. Visit this group at http://groups.google.com/group/sqlalchemy. For more options, visit https://groups.google.com/d/optout.
