Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-10-12
22:18:58 dansmith so it started something with one and then entered another oslo context managed method with a different one
22:19:21 dansmith melwitt: what you're describing would mean that two users hitting the api simultaneously aren't properly isolated from each other
22:21:20 melwitt dansmith: yeah ... I see what you're saying. I was looking through the oslo.db code and put print statements in there, and saw the transaction context object that's created-on-the-fly and cached per transaction was getting used by another DB access before it was finished
22:21:46 dansmith melwitt: right, because we were handing them contexts that were being modified later
22:21:53 dansmith melwitt: so we hand the first thread a context,
22:22:11 dansmith then we change that context when we hand the second/last one its context
22:22:30 dansmith so the first one and the second one are using the same context.db_connection because they share the same context object
22:22:32 dansmith after your change,
22:22:42 dansmith the target_cell yields a new copied context, with the change made,
22:22:51 dansmith and they start their db session with that context
22:23:03 dansmith *they each start
22:24:14 dansmith let me say that again but hopefully more clear:
22:24:29 dansmith let's say we have two cells
22:24:33 melwitt haha, sorry. I have found the whole thing very confusing, even while I was working on it
22:25:19 dansmith hang on a sec, I'm not sure the above is quite right
22:25:28 dansmith it doesn't change the point, but just a sec
22:25:34 melwitt k
22:26:39 dansmith actually, I'm not sure about your fix really
22:27:32 dansmith yeah, so I think the premise in your commit message is wrong
22:28:06 dansmith you say we synchronize access to the cell cache to avoid two things using the context manager at the same time,
22:28:08 dansmith but that's not true,
22:28:33 dansmith we synchronize it so two threads racing to populate the cache won't both create and set the cache entry
22:28:53 dansmith if the cache is already populated, we just grab the results, drop out of the lock, and set it on our context
22:29:03 dansmith then we *use* it later at will, no synchronization
22:29:33 dansmith # Synchronize access to the cache by multiple API workers.
22:29:47 dansmith just the cache to avoid a storm of threads trying to be the first to set the cache entry
22:30:23 dansmith your change should be yielding out a targeted copy of the context which is passed to the thread and never used again,
22:30:32 dansmith and shouldn't be altered by the other iterations of the loop
22:30:58 dansmith so I'm not sure why moving target_cell inside the thread would change anything
22:31:33 melwitt well, wasn't what you said what was happening before my change? yielding a targeted context and passing to the thread?
22:32:06 dansmith I didn't parse that
22:32:29 melwitt sorry. isn't that what was happening before my change? passing a targeted copy of the context to the thread?
22:32:58 dansmith sorry, I meant "before your change" above
22:33:39 dansmith so after your change we're doing the targeting in threads which would increase contention for that section that needs to be locked, not reduce it
22:34:12 dansmith what I thought was happening when I read this change the first time was that we were targeting the context, passing it (assuming by value) and then re-targeting for the next iteration
22:34:18 dansmith since you say set_target_cell in the commit message
22:34:20 dansmith but we weren't
22:34:40 dansmith to link this back,
22:35:34 dansmith in pike's instance list, we're single-threadedly doing each list, and then moving on to the next.. so there should be no overlapping of the execution of set_target_cell() which would mean if that was the problem, it wouldn't show up in list on pike
22:35:48 melwitt well, if one of the threads were populating the cache, without the change, there would be no synchronization of them doing that. right?
22:36:35 dansmith I'm not sure what you mean.. if one of the threads in the scatter?
22:36:52 melwitt yeah if the threads in the scatter were racing to populate the cell cache
22:36:59 dansmith each one is populating a different entry, right? so they're all synchronizing on a different cell_mapping.uuid, so they're not actually locking each other out
22:37:10 melwitt that must have been what I was seeing?
22:37:16 dansmith I don't think so
22:37:20 dansmith because ^
22:38:33 melwitt yeah, that's true. locally, what I was seeing was that an instance.save() was colliding with an instance get
22:39:06 dansmith if that's really happening, we have a huge problem I think, but I don't understand how that could be
22:39:13 melwitt during the instance read, instance write was trying to happen in the same DB transaction
22:39:33 melwitt and I saw the read was happening in the quota check (scatter gather)
22:40:07 melwitt so while it was checking quota, the instance.save() of the resize (I think it was) failed mid-transaction bc it was trying to upgrade the read from the quota check to a write for the instance save
22:40:16 dansmith if this is a problem, it should be a problem with a single cell right?
22:40:28 melwitt yeah, the test setup was cell0 and cell1
22:41:07 dansmith what I mean is before we were doing any cell switching
22:41:36 melwitt oh. yeah I mean I definitely see your point there and I currently don't understand how that isn't an issue
22:41:39 dansmith I don't think this has anything to do with the number of cells you have since it's all per-cell and as we established above, the cache isn't even synchronized across all, it's just on the one cell you're trying to populate
22:41:56 melwitt like, is there something different about us rolling our own green threads via spawn?
22:42:04 dansmith no
22:42:15 dansmith it would be in our handling of the db context manager if anything
22:42:48 melwitt yeah I agree nothing to do with number of cells
22:42:59 dansmith so
22:43:23 melwitt I had thought it was being two threads were trying to use the same context manager at the same time, but that doesn't make sense for the old style "main context manager" that's used by everything
22:43:32 melwitt like you said
22:43:42 dansmith it also doesn't make sense since both threads are using different ones
22:43:49 dansmith for the two cells
22:44:02 dansmith can you -W the backport or something so we don't merge this until we figure out what's going on?
22:44:45 melwitt they were using the same one in this test bc it was a unit test. untargeted context was going to same database cell0 (with my change to default to cell0)
22:44:50 melwitt okay
22:45:06 dansmith and you were scattering to cell0 as well?
22:45:16 sapd_ I can't fix this error!
22:45:31 sapd_ Can you give me any suggest :((
22:46:26 melwitt dansmith: yes. scattering to cell0 and cell1 but since it was a unit test calling resize directly, there was no targeting
22:46:55 melwitt quota check scatters regardless I mean. the context passed to the resize was not targeted so it was trying to save the instance in cell0
22:47:04 dansmith melwitt: so it was a unit test, where were the get and save that were conflicting?
22:47:36 dansmith okay resize was doing the save untargeted,
22:47:39 melwitt dansmith: the get was in the quota check for the new flavor, the save was trying to save the state of the instance for the resize
22:47:43 melwitt right
22:48:07 dansmith but how in a unit test could those be going on at the same time?
22:48:10 dansmith all in the same test right?
22:49:13 melwitt yeah. well, not using SpawnIsSynchonous, real green threads were started for the quota check. but the result should be waited for before proceeding to the save.
22:49:22 dansmith right
22:49:39 melwitt so oslo.db caches "TransactionContext" objects thread locally
22:50:22 melwitt and there was on in there and it was set to read mode, then the save found it and failed when it saw the conflict of trying to do a write mode
22:50:36 melwitt *one in there
22:51:00 dansmith you mean you were in the save, and there was already a transaction context, and you traced that back to the scatter?
22:51:39 melwitt yeah. things worked fine without the scatter involved
22:51:56 dansmith what I mean is, how did you examine that transaction context to know it was from the scatter?
22:52:06 dansmith and where locally does it cache it?
22:52:19 dansmith like in context.db_connection.something ?
22:52:26 melwitt I didn't see a way to link it to the scatter. one sec
22:52:54 melwitt this https://github.com/openstack/oslo.db/blob/master/oslo_db/sqlalchemy/enginefacade.py#L997-L1041
22:53:27 melwitt is how oslo.db does a transaction scope. and what I was seeing is it pulls a transaction context by thread, if it has one, and uses that if it finds it
22:53:33 dansmith that looks like it caches it in TLS,
22:53:36 dansmith which is what I'd expect
22:53:44 melwitt and it was finding one that was in read mode, and it tried to use it to write for the save and it blew up
22:53:59 dansmith right which should mean each thread has its own context, which is the only way this could not be broken :)
22:54:54 dansmith https://github.com/openstack/oslo.db/blob/master/oslo_db/sqlalchemy/enginefacade.py#L1085
22:55:05 melwitt when the transaction goes out of scope, it destroys the cached context for the thread
22:55:21 dansmith right
22:55:24 melwitt but it wasn't destroying it (from the read) and it was using it for a write

Earlier   Later