Posted	Nick	Remark
#openstack-nova - 2017-09-26
22:52:44	mriedem	which makes sense b/c 1 cpu, 1 ram, 1 disk allocation per instance
22:52:49	mriedem	500 in the nova_cell0 db
22:53:48	mriedem	aha
22:53:49	mriedem	Sep 26 22:28:37 devstack nova-scheduler[2951]: WARNING nova.scheduler.client.report [None req-af92d5f2-4c99-4231-966e-939e1da04239 demo admin] Unable to submit allocation for instance 5f9f4f7d-8a2f-4fb8-b30a-024ed2e8e49d (409 {"errors": [{"status": 409, "request_id": "req-cda80554-6083-45b0-87bf-9e9c9924213f", "detail": "There was a conflict when trying to complete your request.\n\n Inventory changed while attempting to alloc
22:53:49	mriedem	ubuntu@devstack:~$ sudo journalctl -a -u devstack@n-sch.service | grep Unable
22:53:50	mriedem	ubuntu@devstack:~$
22:53:50	mriedem	Sep 26 22:28:37 devstack nova-scheduler[2951]: DEBUG nova.scheduler.filter_scheduler [None req-af92d5f2-4c99-4231-966e-939e1da04239 demo admin] Unable to successfully claim against any host. {{(pid=2951) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:221}}
22:53:50	mriedem	Another thread concurrently updated the data. Please retry your update ", "title": "Conflict"}]})
22:54:13	mriedem	and then that removes all allocations for all instances
22:54:19	mriedem	dansmith: melwitt: ^
22:54:27	mriedem	so yeah that's my failure here
22:55:05	melwitt	um, so is that a new scheduling race condition that has to be resolved with reschedules? to replace the old claim race?
22:55:09	mriedem	it does retry http://paste.openstack.org/show/621996/
22:55:21	mriedem	we do a retry in the scheduler
22:56:00	melwitt	yeah, but I thought after "claims in the scheduler" we don't have concurrent request race problems that get kicked out to be retried
22:56:03	mriedem	i don't know why that's logged 6 times
22:56:06	dansmith	I do
22:56:23	mriedem	heh
22:56:24	dansmith	because you're scheduling so many things to one compute, and it only retries a certain number of times
22:56:25	mriedem	do tell :)
22:56:59	mriedem	i'm not surprised it's hitting a conflict
22:57:04	mriedem	but why is that logged 3 times?
22:57:05	dansmith	melwitt: we still have concurrent updates that we have to retry
22:57:07	mriedem	6 i mean
22:57:08	mriedem	https://github.com/openstack/nova/blob/master/nova/scheduler/client/report.py#L1007
22:57:12	mriedem	because ^ we retry 3 times
22:57:37	mriedem	you know, hitting a conflict that we have to retry once in 500 instances with a single compute, is pretty good
22:57:46	mriedem	although i'm not sure which of the 500 this is that falied
22:57:54	melwitt	so this is like the claim race except worse in that the things should have succeeded but can't. maybe it won't happen in real life because by the time that retry limit would be hit, the compute host would already be rejecting claims
22:58:00	dansmith	well, actually.. are you doing one boot there or is there anything else going on?
22:58:18	mriedem	single boot, --min-count 500
22:58:37	mriedem	only thing that could be changing inventory is the RT?
22:58:46	melwitt	oh, okay so all or none. so nvm what I said
22:58:48	dansmith	so we should be only making one call to scheduler I guess
23:00:20	mriedem	hmm, so before claims in the scheduler, if you multi-create, wouldn't we only fail some of these after claims in the compute and reschedules?
23:00:31	mriedem	so chances are you'd have some/most active, but others in error after reschedules?
23:00:46	mriedem	now it's all or none
23:00:53	dansmith	all or none for the claim process
23:00:56	dansmith	you can still fail for other reasons
23:01:10	mriedem	filters i suppose yeah
23:01:27	dansmith	but yeah, people really hate this behavior that we tell them they can boot 500 things and later fail 20% of them because we suck
23:01:32	dansmith	this is much better
23:02:25	dansmith	so I guess my thinking about why these are changing was because of concurrent requests, but if you're just doing one boot, I'm not sure
23:02:32	melwitt	yeah, that's what I was trying to think in real life the retries would have a much better chance of succeeding bc not so many concentrated on one host, right
23:02:53	dansmith	maybe the compute is tickling the inventory in some way, such that during 500 of them it gets changed
23:03:06	melwitt	because the claim would detect the host full and then it would move on to another host
23:03:07	dansmith	melwitt: yeah, I'm pretty confident it's related to the having of one compute and 500 instances
23:04:11	melwitt	the thing I'm wondering is if the host list order is consistent, could this happen in real life because they'll all try the first host in the list first. but as things are claimed, that host will fill up and then no longer be considered
23:04:42	mriedem	melwitt: i'm wondering the same
23:04:48	mriedem	if we're not shuffling the hosts a bit
23:04:49	melwitt	so won't get bombarded that badly?
23:05:56	dansmith	mriedem: I want to know what the instance uuid is for each of those lines
23:06:11	dansmith	mriedem: like maybe it retried once for a few instances, then three times for one and bailed the whole process
23:06:33	dansmith	because any one of them gets to three retries and it should fail and stop the num_instances loop I think
23:06:58	mriedem	5f9f4f7d-8a2f-4fb8-b30a-024ed2e8e49d
23:07:21	mriedem	oh...http://paste.openstack.org/show/621996/
23:07:28	mriedem	we don't have the instance uuid in that message
23:07:43	dansmith	...that's what I'm asking for yeah
23:07:47	mriedem	ok, adding
23:07:56	mriedem	that explains the 6 log messages
23:08:57	dansmith	while you're re-testing, I'd like to suggest that we not hold up the instance list stuff on this if it takes too much longer
23:09:29	dansmith	we can revert it if there's a real performance regression pretty easily, and we're delaying soak-time for any non-perf-related bugs we might be able to resolve just from our own infra workload
23:09:36	mriedem	well, i wasted most of my day on this 500 novalidhost thing,
23:09:43	mriedem	now i know i can create in 100 chunks
23:09:47	dansmith	and we know we're not regressing the performance of the infra jobs that have run against this
23:09:54	mriedem	so i'm at the point that i've got 500 in cell0 and 500 in cell1, and going to get numbers on those
23:12:21	openstackgerrit	Matt Riedemann proposed openstack/nova master: Log instance uuid when retrying claims in the scheduler https://review.openstack.org/507705
23:16:59	openstackgerrit	Moshe Levi proposed openstack/nova master: Don't overwrite binding-profile https://review.openstack.org/505613
23:24:42	openstackgerrit	Ed Leafe proposed openstack/nova-specs master: Return Selection Objects https://review.openstack.org/498830
23:25:48	dansmith	I'm actually not sure why we'd be hitting concurrent updates during an allocation event,
23:25:54	dansmith	given that we're not passing rp_generation
23:26:08	dansmith	either the allocation fits or doesn't
23:27:39	melwitt	hm, yeah
23:27:43	dansmith	it must be that placement doesn't hide transaction commits from us
23:27:46	dansmith	based on the commit that added it
23:28:12	dansmith	which would just be "tons of churn on one provider" as the reason
23:29:57	melwitt	what does that mean? placement not hiding transaction commits
23:31:14	dansmith	an allocation will increment the generation of the provider on the placement side
23:31:23	dansmith	and a transaction will abort if we try to do it at the same time as something else
23:31:26	melwitt	ah, right. that's what I was thinking of
23:31:52	dansmith	placement should really retry those for us server-side I would think, for an allocation type request
23:31:58	melwitt	I couldn't remember where the RP generation was related there
23:32:22	dansmith	doesn't matter, but I would think it would be better, especially given the advice for that error is "try exactly the same thing again"
23:32:24	melwitt	yeah, I was thinking the same
23:32:29	mriedem	this was the error from the server
23:32:30	mriedem	There was a conflict when trying to complete your request.\n\n Inventory changed while attempting to allocate: Another thread concurrently updated the data. Please retry your update
23:32:38	dansmith	right
23:32:41	mriedem	i'm not sure why inventory would change
23:32:45	mriedem	that's static in this case
23:33:01	dansmith	any allocation will change the generation
23:33:04	mriedem	the update_available_resource periodic will post inventory, but only if it changes
23:33:19	dansmith	so any two allocations can conflict
23:33:21	melwitt	I'm +1 on the idea of retrying server-side
23:34:16	melwitt	I'm a little worried how many conflicts can we get in real life by ppl trying to create 500 servers and the scheduler is doing a "pack" pattern
23:35:10	melwitt	as far as how to tune how many retries
23:35:23	melwitt	to allow
23:35:33	dansmith	this is also a highly synthetic scenario with a "virt driver" that doesn't get looked at much.. it could be doing something to re-stab inventory for no reason or something
23:36:00	mriedem	for each instance, we go through the filters
23:36:17	mriedem	and doesn't the scheduler have some kind of tracking on the HostState objects themselves for chosen hosts?
23:36:22	edleafe	mriedem: that error message is poorly worded. It should be something like "available inventory has changed"

Earlier   Later