| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-08-30 | |||
| 20:35:11 | mriedem | http://logs.openstack.org/98/584598/21/check/tempest-full/85acbda/controller/logs/screen-n-cpu.txt.gz#_Aug_29_21_51_13_055225 | |
| 20:35:14 | dansmith | okay this was on startup for me, which prevented it from every reporting initial inventory to placement | |
| 20:35:16 | mriedem | right before the DiskNotFound | |
| 20:35:25 | mriedem | Aug 29 21:51:13.055225 ubuntu-xenial-rax-iad-0001643010 nova-compute[16853]: INFO nova.virt.libvirt.driver [None req-af17b138-d942-4bbf-bf67-4d03b492ed3c tempest-ImagesTestJSON-1980657675 tempest-ImagesTestJSON-1980657675] [instance: 21227895-e216-463f-8e76-998fe637bab2] Deletion of /opt/stack/data/nova/instances/21227895-e216-463f-8e76-998fe637bab2_del complete | |
| 20:35:28 | dansmith | but I had what I think was a stale disk image in my instances directory | |
| 20:35:34 | mriedem | Aug 29 21:51:13.167422 ubuntu-xenial-rax-iad-0001643010 nova-compute[16853]: ERROR nova.compute.manager [None req-6f4285cc-ce12-4c29-b879-99fdaaae59be None None] Error updating resources for node ubuntu-xenial-rax-iad-0001643010.: DiskNotFound: No disk at /opt/stack/data/nova/instances/21227895-e216-463f-8e76-998fe637bab2/disk | |
| 20:35:42 | dansmith | nuking that fixed it, but I just had to do one more thing and then killed it all | |
| 20:35:46 | mriedem | yeah on startup would be a different weirdness | |
| 20:37:39 | Sundar | melwitt: If we can settle everything in one session, that would be great. Given the quantum of reviews, we want to make sure that there is enough convergence to close the spec https://review.openstack.org/#/c/577438 after the PTG. | |
| 20:38:02 | Sundar | Could we keep a 30-minute placeholder? | |
| 20:40:31 | mriedem | so on the 2nd go around in the RT.update_available_resource in this xen CI run, we see the RT say the tracked compute node has changed: | |
| 20:40:33 | mriedem | http://paste.openstack.org/show/729180/ | |
| 20:40:44 | mriedem | b/c of _copy_resources updating the *_allocation_ratio values to 0.0 | |
| 20:42:13 | mriedem | Aug 30 08:03:09.458344 dsvm-devstack-citrix-lon-nodepool-1379396 nova-compute[24292]: INFO nova.compute.resource_tracker [None req-9b1b9924-b89e-4a03-9a69-c9fff17594e3 None None] ComputeNode.cpu_allocation_ratio changed from 16.0 to 0.0 in _copy_resources. | |
| 20:44:50 | melwitt | Sundar: 30-minute placeholder for monday or tuesday? | |
| 20:46:05 | melwitt | Sundar: also, I think we should have the nova bits of the interaction proposed to nova-specs for review, that way we can more easily organize our review on that part | |
| 20:46:48 | Sundar | 30 min in Nova's schedule, anytime you want. Cyborg should allocate at least 1 hour on mon/tue. | |
| 20:47:27 | Sundar | The os-acc spec as a whole is Nova/Cyborg, so do we want another spec? | |
| 20:48:19 | melwitt | Sundar: okay, so you're saying you think we need two sessions. I can try to find a 30-minute slot on our schedule | |
| 20:48:51 | melwitt | Sundar: we need a nova spec for the proposed changes to the nova code, so the nova team can review those proposed changes | |
| 20:50:04 | Sundar | melwitt: Thanks a lot. OK, will propose a Nova spec too. BTW, I have been interacting a lot with efried and any Nova developer who gives feedback on os-acc spec. | |
| 20:50:08 | melwitt | nova meeting in 10 minutes | |
| 20:50:47 | melwitt | Sundar: thanks | |
| 20:52:57 | mriedem | cdent: just so you can rest easy tonight, i think we can safely confirm that we have some sort of weird multi-thread race with shared ProviderTree cache | |
| 20:52:59 | mriedem | https://bugs.launchpad.net/nova/+bug/1789654/comments/9 | |
| 20:52:59 | openstack | Launchpad bug 1789654 in OpenStack Compute (nova) "placement allocation_ratio initialized with 0.0" [High,In progress] - Assigned to Matt Riedemann (mriedem) | |
| 20:52:59 | melwitt | mriedem: so _copy_resources is bypassing the compute node normalization routine? | |
| 20:53:00 | mriedem | efried: ^ | |
| 20:53:32 | mriedem | melwitt: yes, and from my log digging in that comment it shows that if we hit this in the right order, we call ComputeNode.save() which will change the CN.cpu_allocation_ratio from 0.0 (from _copy_resources) back to 16.0 | |
| 20:53:43 | cdent | oh great, I love weird multi-thread races, especially when caches are involved | |
| 20:53:49 | mriedem | which goes to the RT._normalize_inventory_from_cn_obj method which puts 16.0 back into the inventory dict | |
| 20:54:02 | melwitt | mriedem: ah, ok. nice sleuthing | |
| 20:54:13 | mriedem | but there is clearly something else hitting ProviderTree.update_inventory at the same time that RT.update_available_resource is running | |
| 20:54:42 | mriedem | and i don't think it's coming from the RT | |
| 20:54:59 | mriedem | the only place in RT that we call ProviderTree.update_inventory is after driver.update_provider_tree, which isn't implemented for xen | |
| 20:55:09 | mriedem | so i think it's the SchedulerReportClient's provider tree cache | |
| 20:57:37 | cdent | I suspect (or at least hope) that efried will have some insight on the meanderings of the cache | |
| 20:58:06 | efried | I may, once I'm not trying to do several things at once. | |
| 20:59:00 | cdent | efried: this seems to be an unfortunately common problem | |
| 20:59:15 | cdent | let's all quit | |
| 20:59:22 | cdent | (that'll show em) | |
| 20:59:32 | mriedem | meeting in 1 min? | |
| 20:59:48 | melwitt | yes, I gave a 10 minute warning 9 minutes ago | |
| 21:05:13 | mriedem | far as i can tell the report client gets inventory like 500 times a second | |
| 21:05:25 | mriedem | it calls _refresh_and_get_inventory *a lot* | |
| 21:05:37 | mriedem | for every _ensure_resource_provider | |
| 21:05:49 | mriedem | where again, _ensure_resource_provider is less ensure and more "refresh the world" now | |
| 21:13:48 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Log the operation when updating generation in ProviderTree https://review.openstack.org/597553 | |
| 21:13:49 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Add debug logs for when provider inventory changes https://review.openstack.org/597560 | |
| 21:15:14 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Add debug logs for when provider inventory changes https://review.openstack.org/597560 | |
| 21:18:58 | openstackgerrit | Dan Smith proposed openstack/nova master: WIP: Move conductor wait_until_ready() delay before manager init https://review.openstack.org/598353 | |
| 21:19:10 | dansmith | mriedem: can we see if this helps? ^ | |
| 21:20:05 | mriedem | we sure can | |
| 21:21:58 | mriedem | i didn't know conductor_api.wait_until_ready existed | |
| 21:22:01 | mriedem | so see, i did need you | |
| 21:22:25 | dansmith | you need better grep skills, that's all | |
| 21:25:26 | mriedem | i even said in my patch after WPIing it something like "we should really wait until conductor is ready, but what makes it 'ready'" | |
| 21:25:31 | mriedem | i guess this | |
| 21:25:44 | melwitt | wait_until_ready, of course | |
| 21:25:50 | melwitt | (I didn't know about it either) | |
| 21:25:55 | mriedem | ConductorAPI.easy_button() | |
| 21:26:31 | mriedem | what i'd like to do, del nova.compute.resource_tracker | |
| 21:28:35 | melwitt | you and jaypipes and bauzas and everyone else | |
| 21:29:15 | dansmith | well, so far that patch is doing super awesome in the gate | |
| 21:30:40 | jaypipes | dansmith: which patch? | |
| 21:31:04 | jaypipes | damn it, I've got more reading back to do... | |
| 21:31:48 | dansmith | it's annoying that this didn't even capture some basic logs | |
| 21:32:47 | dansmith | unless something else just broke real bad | |
| 21:35:46 | dansmith | ...which is the case, woot. | |
| 21:42:09 | mriedem | jebus h c | |
| 21:42:41 | lbragstad | all the grep skillz you need is just one plugin away | |
| 21:43:13 | mriedem | ctrl+shift+f my man | |
| 21:47:50 | efried | how does a guy install a pycharm plugin? | |
| 21:51:05 | jaypipes | efried: sudo apt install vim? | |
| 21:51:40 | lbragstad | git clone https://github.com/$USER/dotfiles | |
| 21:53:33 | efried | found it. Thanks for nothing, snarks | |
| 21:54:16 | zigo | jaypipes: Real man use joe editor ... | |
| 21:59:39 | jaypipes | zigo: luckily, I'm not a real man. | |
| 22:00:07 | dansmith | mriedem: so should I just make up a fake test for that so we can merge and see if the problem goes away? presumably that's the only way we're really going to know? | |
| 22:04:59 | mriedem | dansmith: is it passing in the gate? | |
| 22:05:01 | mriedem | if so, yeah sure | |
| 22:05:05 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Avoid spurious ComputeNode.save during update_available_resource periodic https://review.openstack.org/598365 | |
| 22:05:19 | mriedem | efried: melwitt: ^ is a thing related to that xen bug | |
| 22:05:22 | mriedem | for allocation ratios | |
| 22:05:38 | mriedem | since i'm not sure how we're actually racing here, i'm not sure if it will actually fix it, | |
| 22:06:12 | melwitt | ack | |
| 22:06:33 | mriedem | but it's about the only thing i can think of that would get us this which f's up the inventory in placement during the periodic: | |
| 22:06:34 | mriedem | Aug 29 16:58:05.483508 dsvm-devstack-citrix-mia-nodepool-1379368 nova-compute[24436]: INFO nova.compute.resource_tracker [None req-a869fa19-aa9d-4335-9816-42ff29b64d48 None None] Using cpu_allocation_ratio 0.0 for node: 2f5a2e04-1b61-4437-ab6e-8dbbf797dc07 | |
| 22:06:39 | efried | mriedem: Doesn't seem to be doing what the commit title says... | |
| 22:06:44 | mriedem | that's logs from the normalize method in the RT | |
| 22:07:02 | dansmith | mriedem: it's passing the stuff that isn't dead on the floor for other reasons | |
| 22:07:15 | mriedem | efried: oh but you must read the full message my friend | |
| 22:07:20 | mriedem | it's a rich tapestry of suck | |
| 22:07:21 | efried | yeah yeah | |
| 22:07:43 | mriedem | and with that, i'm putting my lawn mowin' clothes on and hitting nature | |
| 22:07:47 | efried | I don't see it hurting anything to never write 0.0 to an allocation ratio. | |
| 22:08:06 | efried | unless, as you say, some other suckpoint is using that as a signal to refresh the real values from somewhere else. | |
| 22:08:07 | mriedem | right, i don't think this hurts, it might help | |
| 22:08:09 | efried | In which case that should be change. | |
| 22:08:10 | efried | d | |