[sqlalchemy] Re: Inconsistent results in session.flush()
Michael Bayer wrote: On Mar 17, 2007, at 11:39 AM, Simon King wrote: I had assumed that post_update was only necessary when you are inserting two rows that are mutually dependent, but in this case I wasn't inserting either a ReleaseLine or a Label. I suppose post_update can actually have a knock-on affect across the whole dependency graph. Yes, you are correct. I did the requisite three hours of staring and uncovered the actual condition that led to this problem, which is definitely a bug. Because the second flush() did not require any update operation to either the ReleaseLine or the Label object, the circular dependency graph that would be generated for them just gets thrown away, but that also threw away a processor thats supposed to be setting the release_line_id column on your Branch table. so the fix is, if the circular dependency graph doesnt get generated for a particular cycle between mappers, or if a particular mapper within the cycle isnt included in the circular dependency graph, make sure the flush task for that mapper still gets tacked on to the returned structure so that it can operate on other things external to the cycle, in this case your Branch. the Branch is related to the ReleaseLine/Label via a many-to-one, which was not as stressed in the unit tests so its harder for this issue to pop up (also requires the two separate flushes...so very hard to anticipate this problem). So you can take the post_update out and update to rev 2424. Yep. I can definitely say that I wouldn't have figured that one out. Thanks again for all your help, Cheers, Simon --~--~-~--~~~---~--~~ You received this message because you are subscribed to the Google Groups sqlalchemy group. To post to this group, send email to sqlalchemy@googlegroups.com 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 -~--~~~~--~~--~--~---
[sqlalchemy] Re: Inconsistent results in session.flush()
Michael Bayer wrote: So you can take the post_update out and update to rev 2424. i have a problem with this 2424, before that was ok. As i can't separate a short case now, here the conditions: multi-table-inheritance, polymorphic. Nothing else too fancy. table_Entity has primary db_id, hand-made/sequence obj_id and other data; While populating the database: ... * SA: INFO INSERT INTO Entity (disabled, obj_id, atype) VALUES (?, ?, ?) * SA: INFO [0, 1, 'Person'] * SA: INFO INSERT INTO Person (name_id, db_id) VALUES (?, ?, ) * SA: INFO [2, 1] and now 2423 does: * SA: INFO COMMIT while 2424 does: * SA: INFO INSERT INTO Entity (disabled, obj_id, db_id, atype) VALUES (?, ?, ?, ?) * SA: INFO [0, 1, 1, 'Person'] * SA: INFO ROLLBACK for whatever reason it decides that the same object is dirty AND new, and attempts to reinsert it once more. Any idea? do u want logs? --~--~-~--~~~---~--~~ You received this message because you are subscribed to the Google Groups sqlalchemy group. To post to this group, send email to sqlalchemy@googlegroups.com 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 -~--~~~~--~~--~--~---
[sqlalchemy] Re: Inconsistent results in session.flush()
but sure give me the logs with sqlalchemy.orm == logging.DEBUG On Mar 19, 2007, at 6:49 AM, svilen wrote: Michael Bayer wrote: So you can take the post_update out and update to rev 2424. i have a problem with this 2424, before that was ok. As i can't separate a short case now, here the conditions: multi-table-inheritance, polymorphic. Nothing else too fancy. table_Entity has primary db_id, hand-made/sequence obj_id and other data; While populating the database: ... * SA: INFO INSERT INTO Entity (disabled, obj_id, atype) VALUES (?, ?, ?) * SA: INFO [0, 1, 'Person'] * SA: INFO INSERT INTO Person (name_id, db_id) VALUES (?, ?, ) * SA: INFO [2, 1] and now 2423 does: * SA: INFO COMMIT while 2424 does: * SA: INFO INSERT INTO Entity (disabled, obj_id, db_id, atype) VALUES (?, ?, ?, ?) * SA: INFO [0, 1, 1, 'Person'] * SA: INFO ROLLBACK for whatever reason it decides that the same object is dirty AND new, and attempts to reinsert it once more. Any idea? do u want logs? --~--~-~--~~~---~--~~ You received this message because you are subscribed to the Google Groups sqlalchemy group. To post to this group, send email to sqlalchemy@googlegroups.com 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 -~--~~~~--~~--~--~---
[sqlalchemy] Re: Inconsistent results in session.flush()
On Mar 16, 9:50 pm, Michael Bayer [EMAIL PROTECTED] wrote: oh, this is easy. you have a circular insert relationship between label and release_line, which you can see in the sort there (the cycles:) as well as evidenced by the fact that you have a use_alter needed in order to create the foreign keys on those two tables. add post_update=True to one of the relationships which will break that particular cycle by using a second UPDATE statement, and youre in. Brilliant - that did it. Thanks a lot. Is there any way that SA could have raised an error in this situation? I think this would be very tricky for someone unfamiliar with the SA internals to debug, particularly as it doesn't occur every time. Are there situations where it is reasonable to have cycles without post_update? I had assumed that post_update was only necessary when you are inserting two rows that are mutually dependent, but in this case I wasn't inserting either a ReleaseLine or a Label. I suppose post_update can actually have a knock-on affect across the whole dependency graph. Anyway, thanks a lot again for your help, Simon --~--~-~--~~~---~--~~ You received this message because you are subscribed to the Google Groups sqlalchemy group. To post to this group, send email to sqlalchemy@googlegroups.com 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 -~--~~~~--~~--~--~---
[sqlalchemy] Re: Inconsistent results in session.flush()
On Mar 16, 2007, at 6:59 AM, King Simon-NFHD78 wrote:
Unfortunately I don't know how to go about debugging this. I think I
need to see exactly what is going on in the dependency sort. Do you
have
any suggestions for suitable places to add some extra logging?
these issues are often due to bugs in unitofwork.py and are
unbelievably tough to debug. which is why youre probably going to
have to get a test case for me since I really need to nail all of
these. if you want to turn on all logging available, youd say
logger.getLogger('sqlalchemy.orm').setLevel(logging.DEBUG), and youll
get a whole lot of stuff...after seeing all the logger names you can
tune out some of the noise with additional setLevel statements.
theres also a monkeypatch thats in the test suite which i use for
these, it intentionally reverses the order of topological sorts in
order to flush these out, it looks like:
from sqlalchemy.orm import unitofwork
from sqlalchemy import topological
class RevQueueDepSort(topological.QueueDependencySorter):
def __init__(self, tuples, allitems):
self.tuples = list(tuples)
self.allitems = list(allitems)
self.tuples.reverse()
self.allitems.reverse()
topological.QueueDependencySorter = RevQueueDepSort
unitofwork.DependencySorter = RevQueueDepSort
but when i get these, it takes me a few hours to wrap my head around
the issue, and im the one who wrote the code...so dont knock yourself
out on it...
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
sqlalchemy group.
To post to this group, send email to sqlalchemy@googlegroups.com
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
-~--~~~~--~~--~--~---
[sqlalchemy] Re: Inconsistent results in session.flush()
I can actually read a fair degree from these dumps, i need mostly to know what the actual dependencies are (i.e. which classes are dependent on what, whats the error). also when you do the full debug echoing the UOW should illustrate a series of dependency tuples which will show what pairs of classes the UOW perceives as dependent on each other. On Mar 16, 2007, at 6:59 AM, King Simon-NFHD78 wrote: Hi, I'm having a problem where the results of session.flush() vary from one run to another of my test suite. The unit of work transaction dump is significantly different from one run to the next, similar to the issue in ticket 461. I haven't managed to make a test case small enough to post to the list yet, and I think I need to delve a little further into the code to find out why it's failing. (This is with both 0.3.5 and rev2416) The logs from the UOWTransaction on a failing run and a passing run are below. As well as the ordering being different, there is at least one class (ReleaseLine) that doesn't appear in the bad run. Unfortunately I don't know how to go about debugging this. I think I need to see exactly what is going on in the dependency sort. Do you have any suggestions for suitable places to add some extra logging? This is a failing run: INFO:sqlalchemy.orm.unitofwork.UOWTransaction.0x..30:Task dump: UOWTask(0x184b2b0, Component/component/None) (save/update phase) | |- UOWTask(0x184bb50, User/user/None) (save/update phase) | |- Save User(0x1851870) | | |- Process User(0x1851870).branches | | |- Process User(0x1851870).reviews | | |- Process User(0x1851870).labels | | |- Process Branch(0x17ee310).user | | |- Process Branch(0x184b190).user | | | |- UOWTask(0x184bb70, ChangeOrigin/change_origin/None) (save/update phase) | | | |- Process Branch(0x17ee310).change_origin | | | |- Process Branch(0x184b190).change_origin | | | | | |- UOWTask(0x184b590, Label/label/None) (save/update phase) | | | | | | | |- UOWTask(0x184b1b0, Branch/branch/None) (save/update phase) | | | | |- Save Branch(0x17ee310) | | | | |- Save Branch(0x184b190) | | | | | |- Process Branch(0x17ee310).review | | | | | |- Process Branch(0x184b190).review | | | | | | | | | |- UOWTask(0x183f470, Review/review/None) (save/update phase) | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb30, sqlalchemy.orm.dependency.MapperStub object at 0x0183FDF0) (save/update phase) | | | | | | |- Process Branch(0x17ee310).label | | | | | | |- Process Branch(0x184b190).label | | | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bfb0, Counter/counter/None) (save/ update phase) | | | | |- Save Counter(0x184b0f0) | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb50, User/user/None) (delete phase) | | | |- UOWTask(0x184bb70, ChangeOrigin/change_origin/None) (delete phase) | | | | | |- UOWTask(0x184b590, Label/label/None) (delete phase) | | | | | | | |- UOWTask(0x184b1b0, Branch/branch/None) (delete phase) | | | | | | | | | |- UOWTask(0x183f470, Review/review/None) (delete phase) | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb30, sqlalchemy.orm.dependency.MapperStub object at 0x0183FDF0) (delete phase) | | | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bfb0, Counter/counter/None) (delete phase) | | | | | | | | | | | | | | | | | | | | | | | | | And on a good run looks like this: INFO:sqlalchemy.orm.unitofwork.UOWTransaction.0x..f0:Task dump: UOWTask(0x17f2610, User/user/None) (save/update phase) |- Save User(0x17fe9f0) | |- Process User(0x17fe9f0).labels | |- Process Branch(0x17caa10).user | |- Process Branch(0x17f2470).user | |- Process User(0x17fe9f0).reviews | |- Process User(0x17fe9f0).branches | |- UOWTask(0x17f2a50, ChangeOrigin/change_origin/None) (save/update phase) | | |- Process Branch(0x17caa10).change_origin | | |- Process Branch(0x17f2470).change_origin | | | |- UOWTask(0x17f29f0, Component/component/None) (save/update phase) | | | | | |- UOWTask(0x17f2ad0, ReleaseLine/release_line/None) (save/update phase) | | | | |- Process Branch(0x17caa10).release_line | | | |
[sqlalchemy] Re: Inconsistent results in session.flush()
I've just run the attached script about thirty times, and it succeeded 5 times and failed the rest. I've cut out a lot of unnecessary stuff, but it's still a bit long I'm afraid. I'll cut it down some more, but since you seemed so eager to see it ;-) I thought I'd send it along as is. On a bad run, the dependency tuples look like this: DEBUG:sqlalchemy.orm.unitofwork.UOWTransaction.0x..50:Dependency sort: Mapper|User|user Mapper|Component|component Mapper|ChangeOrigin|change_origin Mapper|Label|label (cycles: [Mapper|Label|label, Mapper|ReleaseLine|release_line]) Mapper|Counter|counter Mapper|Branch|branch sqlalchemy.orm.dependency.MapperStub object at 0x00D59590 And on a good run they look like this: DEBUG:sqlalchemy.orm.unitofwork.UOWTransaction.0x..10:Dependency sort: Mapper|User|user Mapper|Component|component Mapper|ChangeOrigin|change_origin Mapper|ReleaseLine|release_line (cycles: [Mapper|ReleaseLine|release_line, Mapper|Label|label]) Mapper|Counter|counter Mapper|Branch|branch sqlalchemy.orm.dependency.MapperStub object at 0x00D59670 Thanks a lot for looking at this, Simon Michael Bayer wrote: I can actually read a fair degree from these dumps, i need mostly to know what the actual dependencies are (i.e. which classes are dependent on what, whats the error). also when you do the full debug echoing the UOW should illustrate a series of dependency tuples which will show what pairs of classes the UOW perceives as dependent on each other. On Mar 16, 2007, at 6:59 AM, King Simon-NFHD78 wrote: Hi, I'm having a problem where the results of session.flush() vary from one run to another of my test suite. The unit of work transaction dump is significantly different from one run to the next, similar to the issue in ticket 461. I haven't managed to make a test case small enough to post to the list yet, and I think I need to delve a little further into the code to find out why it's failing. (This is with both 0.3.5 and rev2416) The logs from the UOWTransaction on a failing run and a passing run are below. As well as the ordering being different, there is at least one class (ReleaseLine) that doesn't appear in the bad run. Unfortunately I don't know how to go about debugging this. I think I need to see exactly what is going on in the dependency sort. Do you have any suggestions for suitable places to add some extra logging? This is a failing run: INFO:sqlalchemy.orm.unitofwork.UOWTransaction.0x..30:Task dump: UOWTask(0x184b2b0, Component/component/None) (save/update phase) | |- UOWTask(0x184bb50, User/user/None) (save/update phase) | |- Save User(0x1851870) | | |- Process User(0x1851870).branches | | |- Process User(0x1851870).reviews | | |- Process User(0x1851870).labels | | |- Process Branch(0x17ee310).user | | |- Process Branch(0x184b190).user | | | |- UOWTask(0x184bb70, ChangeOrigin/change_origin/None) (save/update phase) | | | |- Process Branch(0x17ee310).change_origin | | | |- Process Branch(0x184b190).change_origin | | | | | |- UOWTask(0x184b590, Label/label/None) (save/update phase) | | | | | | | |- UOWTask(0x184b1b0, Branch/branch/None) (save/update phase) | | | | |- Save Branch(0x17ee310) | | | | |- Save Branch(0x184b190) | | | | | |- Process Branch(0x17ee310).review | | | | | |- Process Branch(0x184b190).review | | | | | | | | | |- UOWTask(0x183f470, Review/review/None) (save/update phase) | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb30, sqlalchemy.orm.dependency.MapperStub object at 0x0183FDF0) (save/update phase) | | | | | | |- Process Branch(0x17ee310).label | | | | | | |- Process Branch(0x184b190).label | | | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bfb0, Counter/counter/None) (save/ update phase) | | | | |- Save Counter(0x184b0f0) | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb50, User/user/None) (delete phase) | | | |- UOWTask(0x184bb70, ChangeOrigin/change_origin/None) (delete phase) | | | | | |- UOWTask(0x184b590, Label/label/None) (delete phase) | | | | | | | |- UOWTask(0x184b1b0, Branch/branch/None) (delete phase) | | | | | | | | | |- UOWTask(0x183f470, Review/review/None) (delete phase) | | | | | | | | | | | | | | |
[sqlalchemy] Re: Inconsistent results in session.flush()
oh, this is easy. you have a circular insert relationship between label and release_line, which you can see in the sort there (the cycles:) as well as evidenced by the fact that you have a use_alter needed in order to create the foreign keys on those two tables. add post_update=True to one of the relationships which will break that particular cycle by using a second UPDATE statement, and youre in. On Mar 16, 2007, at 1:58 PM, King Simon-NFHD78 wrote: I've just run the attached script about thirty times, and it succeeded 5 times and failed the rest. I've cut out a lot of unnecessary stuff, but it's still a bit long I'm afraid. I'll cut it down some more, but since you seemed so eager to see it ;-) I thought I'd send it along as is. On a bad run, the dependency tuples look like this: DEBUG:sqlalchemy.orm.unitofwork.UOWTransaction.0x..50:Dependency sort: Mapper|User|user Mapper|Component|component Mapper|ChangeOrigin|change_origin Mapper|Label|label (cycles: [Mapper|Label|label, Mapper|ReleaseLine|release_line]) Mapper|Counter|counter Mapper|Branch|branch sqlalchemy.orm.dependency.MapperStub object at 0x00D59590 And on a good run they look like this: DEBUG:sqlalchemy.orm.unitofwork.UOWTransaction.0x..10:Dependency sort: Mapper|User|user Mapper|Component|component Mapper|ChangeOrigin|change_origin Mapper|ReleaseLine|release_line (cycles: [Mapper|ReleaseLine|release_line, Mapper|Label|label]) Mapper|Counter|counter Mapper|Branch|branch sqlalchemy.orm.dependency.MapperStub object at 0x00D59670 Thanks a lot for looking at this, Simon Michael Bayer wrote: I can actually read a fair degree from these dumps, i need mostly to know what the actual dependencies are (i.e. which classes are dependent on what, whats the error). also when you do the full debug echoing the UOW should illustrate a series of dependency tuples which will show what pairs of classes the UOW perceives as dependent on each other. On Mar 16, 2007, at 6:59 AM, King Simon-NFHD78 wrote: Hi, I'm having a problem where the results of session.flush() vary from one run to another of my test suite. The unit of work transaction dump is significantly different from one run to the next, similar to the issue in ticket 461. I haven't managed to make a test case small enough to post to the list yet, and I think I need to delve a little further into the code to find out why it's failing. (This is with both 0.3.5 and rev2416) The logs from the UOWTransaction on a failing run and a passing run are below. As well as the ordering being different, there is at least one class (ReleaseLine) that doesn't appear in the bad run. Unfortunately I don't know how to go about debugging this. I think I need to see exactly what is going on in the dependency sort. Do you have any suggestions for suitable places to add some extra logging? This is a failing run: INFO:sqlalchemy.orm.unitofwork.UOWTransaction.0x..30:Task dump: UOWTask(0x184b2b0, Component/component/None) (save/update phase) | |- UOWTask(0x184bb50, User/user/None) (save/update phase) | |- Save User(0x1851870) | | |- Process User(0x1851870).branches | | |- Process User(0x1851870).reviews | | |- Process User(0x1851870).labels | | |- Process Branch(0x17ee310).user | | |- Process Branch(0x184b190).user | | | |- UOWTask(0x184bb70, ChangeOrigin/change_origin/None) (save/update phase) | | | |- Process Branch(0x17ee310).change_origin | | | |- Process Branch(0x184b190).change_origin | | | | | |- UOWTask(0x184b590, Label/label/None) (save/update phase) | | | | | | | |- UOWTask(0x184b1b0, Branch/branch/None) (save/update phase) | | | | |- Save Branch(0x17ee310) | | | | |- Save Branch(0x184b190) | | | | | |- Process Branch(0x17ee310).review | | | | | |- Process Branch(0x184b190).review | | | | | | | | | |- UOWTask(0x183f470, Review/review/None) (save/update phase) | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb30, sqlalchemy.orm.dependency.MapperStub object at 0x0183FDF0) (save/update phase) | | | | | | |- Process Branch(0x17ee310).label | | | | | | |- Process Branch(0x184b190).label | | | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bfb0, Counter/counter/None) (save/ update phase) | | | | |- Save Counter(0x184b0f0) | | | | | | | | | | | | | | | | | | | | | | | | | |- UOWTask(0x184bb50, User/user/None) (delete phase) | | | |- UOWTask(0x184bb70,
