| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2020-07-16 | |||
| 21:19:51 | openstackgerrit | Lee Yarwood proposed openstack/nova master: Ensure source compute is up when confirming a resize https://review.opendev.org/699291 | |
| 21:20:22 | mnaser | interestingly enough, all os_vif ops are taking almost 4-5s | |
| 21:20:51 | mnaser | and i think os_vif is just local only? | |
| 21:21:32 | melwitt | yeah, I think so | |
| 21:37:02 | dansmith | melwitt: ersum, thanks | |
| 21:37:40 | melwitt | yer welcome | |
| 21:42:22 | openstackgerrit | Stephen Finucane proposed openstack/nova master: api: Reject non-spawn operations for vTPM https://review.opendev.org/741500 | |
| 21:42:23 | openstackgerrit | Stephen Finucane proposed openstack/nova master: libvirt: Add emulated TPM support to Nova https://review.opendev.org/631363 | |
| 21:42:23 | openstackgerrit | Stephen Finucane proposed openstack/nova master: docs: Add docs for vTPM support https://review.opendev.org/739213 | |
| 21:42:24 | openstackgerrit | Stephen Finucane proposed openstack/nova master: WIP: Add support for resize and cold migration of emulated TPM files https://review.opendev.org/639934 | |
| 21:56:32 | openstackgerrit | Tobias Urdin proposed openstack/nova master: [PoC] libvirt: Broadcast RARP post live migration https://review.opendev.org/741529 | |
| 21:57:37 | openstackgerrit | Tobias Urdin proposed openstack/nova master: [PoC] libvirt: Broadcast RARP post live migration https://review.opendev.org/741529 | |
| 23:04:33 | openstackgerrit | Artom Lifshitz proposed openstack/nova master: Handle Neutron errors in _post_live_migration() https://review.opendev.org/729763 | |
| 23:12:09 | openstackgerrit | Lee Yarwood proposed openstack/nova master: WIP libvirt: Check if device is listed in the inactive config during detach https://review.opendev.org/741557 | |
| 23:44:39 | mnaser | melwitt: further investigation shows that that the vms are taking a long time because of plugging ports | |
| 23:44:57 | mnaser | but .. https://www.irccloud.com/pastebin/WAiTYOJE/ .. vif_plugging_timeout is 300, except it took almost 10 minutes to plug em | |
| 23:52:58 | openstackgerrit | Lee Yarwood proposed openstack/nova master: WIP libvirt: Handle VIR_ERR_DEVICE_MISSING when detaching devices https://review.opendev.org/741561 | |
| #openstack-nova - 2020-07-17 | |||
| 00:17:34 | openstackgerrit | Merged openstack/nova master: libvirt: Add vTPM config support https://review.opendev.org/739209 | |
| 00:31:41 | openstackgerrit | Merged openstack/nova master: zuul: remove legacy-tempest-dsvm-neutron-dvr-multinode-full https://review.opendev.org/740447 | |
| 01:29:10 | sean-k-mooney | mnaser: that general indeicates an issue with neutron or rabbitmq performance | |
| 01:29:54 | mnaser | sean-k-mooney: yeah, so based on my log tracing, the PUT is sent at :33 but n-ovs-agent doesnt actually plug until :37 | |
| 01:30:34 | sean-k-mooney | the PUT? | |
| 01:30:49 | mnaser | sorry, the PUT from n-cpu to neutron to plug the port | |
| 01:30:57 | sean-k-mooney | that is not pluging | |
| 01:31:01 | sean-k-mooney | that is port binding | |
| 01:31:08 | sean-k-mooney | they are two differnt things | |
| 01:31:18 | sean-k-mooney | binding happens before pluging starts | |
| 01:31:45 | mnaser | sean-k-mooney: what triggers the plug? | |
| 01:32:30 | sean-k-mooney | after teh ports are bound nova plugs the interface which in the case of ovs is the act of createing the ovs port | |
| 01:33:01 | sean-k-mooney | when the port is created the external_id in other_cofnig on the ovs interface is set to the neutron port uuid | |
| 01:33:21 | sean-k-mooney | that triggeres an event on a unix socket that the l2 agent is monitoring | |
| 01:33:37 | sean-k-mooney | and then the l2 agent start wiring up the port | |
| 01:33:43 | mnaser | the PUT is the only operation i'm seeing towards neutron-server which isn't read-only (aka not a GET) | |
| 01:34:06 | sean-k-mooney | when the port is wired up and the dhcps agnet has also updated the dhcp config the pluging evnet is sent | |
| 01:34:26 | sean-k-mooney | mnaser: nova does not talk to neutron during plugin | |
| 01:34:42 | sean-k-mooney | it configure the network backend and neutron watches for that | |
| 01:34:55 | sean-k-mooney | when the l2 agent finsihs it send a rpc to the neutron server | |
| 01:35:01 | sean-k-mooney | and that trivers teh event to nova | |
| 01:35:14 | sean-k-mooney | *triggers | |
| 01:35:56 | mnaser | so n-ovs-agent waits for os_vif to do its thing, and then when it sees a new port, it starts the process of wiring it up (aka the whole vlan dance), tells neutron its plugged and then neutron-server does the notify http call? | |
| 01:36:13 | sean-k-mooney | yes | |
| 01:36:24 | mnaser | (fwiw this is stein) | |
| 01:36:43 | sean-k-mooney | yep this dance has not change since neutron was qunantum | |
| 01:36:49 | sean-k-mooney | at least not for spwan | |
| 01:36:52 | mnaser | TIL a lot | |
| 01:37:05 | sean-k-mooney | live migration has changed but spawn is still the same | |
| 01:37:18 | mnaser | ok so once the port is setup by nova and it starts waiting for external event, n-ovs-agent should technically start acting right away | |
| 01:37:47 | sean-k-mooney | yes on older version when the l2 agent was using vsctl instead of the ovs python binding | |
| 01:37:57 | sean-k-mooney | it used to poll for the port updates | |
| 01:38:09 | sean-k-mooney | so there was more latency but it was minimal | |
| 01:38:42 | mnaser | sean-k-mooney: well in that case, the theory is that n-ovs-agent is taking a long time to notice the port appearing | |
| 01:39:03 | sean-k-mooney | mnaser: the condition for sending the network_vif_plugged event have 3 parts | |
| 01:39:13 | sean-k-mooney | 1 the prot is bound and active on a host | |
| 01:39:24 | sean-k-mooney | 2 the agent has finishiend its vlan dance | |
| 01:39:37 | sean-k-mooney | 3 the dhcp agent has complted configing dhcp | |
| 01:39:49 | mnaser | sean-k-mooney: because when i grep n-ovs-agent logs, i see the first 'record' of something happening with that port id is 21:37, few seconds before nova gets notified. that tells me that n-ovs-agent didn't see the port right away? | |
| 01:39:50 | sean-k-mooney | 3 can get very slow at scale | |
| 01:40:06 | mnaser | ah | |
| 01:40:11 | mnaser | so maybe #3 is the issue here | |
| 01:40:19 | mnaser | fwiw, this is doing like | |
| 01:40:44 | mnaser | almost 250 near-concurrent port plugs | |
| 01:41:05 | sean-k-mooney | mnaser: i would the time stamps for 1 os-vif adding the port to ovs, 2 l2 agent seeign the port, 3 dhcp agent seting it up | |
| 01:41:21 | sean-k-mooney | mnaser: ah ha... and that causes issues :) | |
| 01:41:36 | sean-k-mooney | let me see if i have any of the down stream bugs | |
| 01:41:53 | sean-k-mooney | i know our networkg folk have had issue form customer related to the dhcp agent | |
| 01:42:04 | sean-k-mooney | it might not be the same but it sound similar | |
| 01:42:48 | mnaser | oh this is interesting | |
| 01:43:04 | mnaser | https://www.irccloud.com/pastebin/vjt0J52B/ | |
| 01:43:18 | mnaser | sean-k-mooney: almost 3 minutes for os_vif to plug the port? | |
| 01:43:45 | mnaser | but i guess, "Plugging" is the step 1 | |
| 01:43:52 | mnaser | and then "Plugged" happens after getting the external event | |
| 01:44:31 | sean-k-mooney | yes i think so but i cna check quickly where that log is | |
| 01:44:36 | mnaser | the first 'reference' to that port id in the neutron logs is at 2020-07-16 21:37:27.517 (port xx updated) | |
| 01:44:52 | mnaser | (neutron ovs logs that is) | |
| 01:45:12 | mnaser | 2020-07-16 21:37:34.415 3862298 INFO neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-bda6aed7-6f44-474a-9e4a-ff6082e7bc9e - - - - -] Configuration for devices up ['66278068-7509-40cb-8773-ed4d36801723'] and devices down [] completed. | |
| 01:45:54 | mnaser | so the 'successfully plugged' comes in 15 seconds after neutron says im all good | |
| 01:46:54 | sean-k-mooney | so pluging started at 40,342,704 | |
| 01:47:06 | sean-k-mooney | that didnt work | |
| 01:47:12 | sean-k-mooney | 2020-07-16 21:34:21.726 | |
| 01:47:46 | sean-k-mooney | so ya the l2 agent too 3 minutes | |
| 01:48:14 | mnaser | os_vif considers it plugged when the external id gets filled in? | |
| 01:49:32 | sean-k-mooney | no | |
| 01:49:38 | sean-k-mooney | https://github.com/openstack/os-vif/blob/8042e41f1bfc4b4d279934a0bed94f77454faeff/os_vif/__init__.py#L78 | |
| 01:49:53 | sean-k-mooney | that message gets retruned when we finish adding the port to ovs | |
| 01:50:07 | mnaser | so it took us 3 minutes to simply add a port into ovs o_O | |
| 01:50:20 | sean-k-mooney | that is what it looks like | |
| 01:50:43 | sean-k-mooney | mnaser: are you using the ovs-vsctl backend or python bindings | |
| 01:51:08 | mnaser | sean-k-mooney: i haven't touched it -- but looking at the code, os_vif defaults to ovs-vsctl but neutron switched to python bindings a while back | |
| 01:51:33 | sean-k-mooney | the default is vsctl | |
| 01:51:35 | sean-k-mooney | https://github.com/openstack/os-vif/blob/stable/stein/vif_plug_ovs/ovs.py#L65-L68 | |
| 01:51:38 | sean-k-mooney | in stien | |
| 01:52:22 | mnaser | im looking at the ovs logs | |
| 01:52:42 | sean-k-mooney | actully its still the defaul... i really though i changed that before neutron did | |
| 01:53:20 | mnaser | i guess that means | |
| 01:53:27 | mnaser | i can grep the logs to find an ovs-vsctl command | |
| 01:54:19 | sean-k-mooney | yes but i know where to check the code :) im wondering if we are using --no-wait. i think we are | |
| 01:55:17 | mnaser | this is interesting though https://www.irccloud.com/pastebin/DERdqYGW/ | |
| 01:56:27 | sean-k-mooney | well its making an external call so eventlit will context switch and start running other code | |
| 01:56:44 | mnaser | sean-k-mooney: with debug=true, im not seeing any executions grepping vsctl or ovs | |
| 01:57:13 | sean-k-mooney | https://github.com/openstack/os-vif/blob/stable/ussuri/vif_plug_ovs/ovsdb/impl_vsctl.py#L333-L335 | |