| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2020-07-17 | |||
| 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 | |
| 01:57:22 | sean-k-mooney | im not sure we are using --no-wait | |
| 01:57:35 | sean-k-mooney | --no-wait return when the port is added to the db | |
| 01:58:03 | sean-k-mooney | without it ovs-vsctl blocks for the dataplane to acknolage that it has create teh port | |
| 01:58:33 | mnaser | i guess i have to find privsep logs | |
| 01:59:02 | mnaser | cause n-cpu doesnt contain any execution logs | |
| 01:59:05 | sean-k-mooney | they are part of the nova compute logs | |
| 02:00:08 | mnaser | ps show 25% cpu usage for the privsep proc for ovs | |
| 02:00:36 | sean-k-mooney | we reduce the privsep logs to info by default https://github.com/openstack/nova/blob/master/nova/config.py#L58 | |
| 02:01:01 | mnaser | ah that's probably why it's not visible | |
| 02:01:24 | sean-k-mooney | ya prvisep in debug mode dupms sensitive info live vm console to the logs | |
| 02:01:43 | sean-k-mooney | so we do not enable privsep debug logs wehn you enable nova's debug logging | |
| 02:02:26 | sean-k-mooney | anyway there are a few things that could be happening. | |
| 02:02:50 | sean-k-mooney | 1 nova could be bussy and wehn we context switch away it might take a while before we get back | |
| 02:03:03 | sean-k-mooney | 2 ovs could be taking a long time to add the port | |
| 02:03:10 | sean-k-mooney | if it is you would see this in the ovs db log | |
| 02:03:29 | sean-k-mooney | it will have a log of when the port add is started and complete i belive | |
| 02:04:12 | mnaser | ovsdb-server has no output (well, almost nothing) but vswitchd has a bunch | |
| 02:04:38 | melwitt | I thought it was pluggin' | |
| 02:04:58 | sean-k-mooney | melwitt: it is | |
| 02:05:10 | sean-k-mooney | but there is a 3 minitu gap betwen it starting and finishing | |
| 02:05:14 | melwitt | I know, just replying super late | |
| 02:05:43 | mnaser | i see a bunch of this: `ovs_rcu(urcu5)|WARN|blocked 1000 ms waiting for main to quiesce` | |
| 02:06:29 | sean-k-mooney | mnaser: in the vswitchd log you should seee somthign like this | |
| 02:06:31 | sean-k-mooney | 2020-05-06T19:52:07.865Z|00031|bridge|INFO|bridge br-int: added interface tap36660a66-00 on port 3 | |
| 02:06:50 | mnaser | ah, yes | |
| 02:07:37 | sean-k-mooney | i think you are looking for tap66278068-75 | |
| 02:07:39 | mnaser | 2020-07-16T21:37:25.283Z|11608|bridge|INFO|bridge br-int: added interface qvo66278068-75 on port 32307 | |
| 02:08:01 | sean-k-mooney | ah you are using iptables | |
| 02:08:23 | sean-k-mooney | not the contrack security group driver? | |
| 02:08:29 | mnaser | yes, there's a plan to move towards openvswitch driver | |
| 02:08:35 | mnaser | iptables_hybrid right now | |
| 02:08:56 | sean-k-mooney | yep that is why the interface name is diffrent | |
| 02:09:52 | sean-k-mooney | given it started plugging at 21:34:21.726 | |
| 02:09:56 | sean-k-mooney | that took a while | |
| 02:10:53 | sean-k-mooney | plugging finished at 21:37:49.943 | |
| 02:11:20 | sean-k-mooney | there is still a 24 second gap but that is more resonably | |
| 02:11:29 | mnaser | so either: nova is 'distracted' doing something else and not actually running ovs-vsctl commands? | |
| 02:11:41 | mnaser | or the ovs-vsctl command is actually taking 3 minutes | |
| 02:12:27 | sean-k-mooney | it could be that its in the queue of peneding funciton to execute in privsep for a while too | |
| 02:13:00 | mnaser | that's very likely because | |
| 02:13:13 | mnaser | https://www.irccloud.com/pastebin/hv0DDE8m/ | |
| 02:13:20 | mnaser | 25% cpu usage for privsep sounds off | |
| 02:14:04 | sean-k-mooney | i dont know didnt you say your creating 250 port/vms at the same time | |
| 02:14:28 | sean-k-mooney | but i think stein predates privsep multi threading | |
| 02:14:58 | mnaser | i mean, they're not all 250 ports there, but i've seen a case of 15 vms spawning at teh same time here | |
| 02:15:14 | mnaser | so 15 vms * 5 ports each = 75 ports being attached together at elast | |
| 02:18:06 | sean-k-mooney | so there are a few things you could try | |
| 02:18:35 | sean-k-mooney | if i am remeberign correctly the native ovsdb interface in os-vif does not use privsep | |
| 02:19:17 | mnaser | https://docs.openstack.org/releasenotes/oslo.privsep/stein.html -- "Privsep now uses multithreading to allow concurrency in executing privileged commands. The number of concurrent threads defaults to the available CPU cores, but can be adjusted by the new thread_pool_size config option." | |
| 02:20:11 | mnaser | and i have privsep 1.32.1 -- cool, so that's taken care of -- i think moving to native ovsdb is probably much better/cleaner | |
| 02:20:38 | sean-k-mooney | you can set ovsdb_interface="native" in the nova.conf | |
| 02:20:43 | sean-k-mooney | but im just checkign the group | |