| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2020-04-20 | |||
| 23:25:52 | sean-k-mooney | abaindur: for what it si worth the port binding events shoudl work with or without post copy | |
| 23:27:12 | sean-k-mooney | _post_live_migration is the function that cleans up the image on the source node and finishes and work reqiured on the dest | |
| 23:28:05 | sean-k-mooney | if you are using a nova and neutron that do not support multiple port bining _post_live_migration_at_dest is where we will do the port binding | |
| 23:29:06 | sean-k-mooney | but in a nova that support neutron multiple port bindign api we will prebind the port on the souce and activate it either in responce to the live migrion even tor the start of _post_live_migration | |
| 23:29:16 | abaindur | yea, but we noticed that in pre-copy LV mode, the port binding activate call is sent towards the end of that function. And connectivity is disrupted when VM is Paused. | |
| 23:29:18 | abaindur | https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L6931 | |
| 23:29:45 | sean-k-mooney | ya so are you using ovs with the ovs firewall driver by any chance | |
| 23:29:51 | abaindur | and here is where the port binding activation call is invoekd: https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L7005 | |
| 23:29:52 | sean-k-mooney | or are you using iptables | |
| 23:30:42 | abaindur | between those 2 lines of code, we noticed nova taking 18+ seconds - 2 seocnds for bolume cleanup, few more seconds for disconnection, 5 sec for get_instance_nw_info, 5 more sec for compute_utils.notify_about_instance_action, etc... | |
| 23:31:01 | abaindur | One the port binding activate call came, another 3-5 seconds for port to be plugged by OVS-agent | |
| 23:31:04 | abaindur | we're using iptables | |
| 23:31:26 | sean-k-mooney | on what release | |
| 23:31:33 | abaindur | Rocky | |
| 23:31:49 | sean-k-mooney | the iptable firewall should have less downtime the openvswithc | |
| 23:32:34 | sean-k-mooney | as we can pre plug the port and have neutron wire it up while we are waiting for migration too happen at the libvirt level. | |
| 23:33:08 | sean-k-mooney | when using the ovs firewall driver because libvirt recreate the ovs port it takes longer as neutron has to do it twice | |
| 23:33:14 | abaindur | as mentioned, we're seeing non-trivial downtime in that _post_live_migration() function on the src host, between the log "'_post_live_migration() is started.." (or when VM is Paused), and when neutron receives the port-binding /activate call at https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L7005 | |
| 23:33:40 | sean-k-mooney | abaindur: yes but before the multiple port binding change it used to be even longer | |
| 23:34:04 | abaindur | so is that down time then to be expected or unavoidable? :( | |
| 23:34:23 | sean-k-mooney | no its avoidable | |
| 23:34:31 | sean-k-mooney | so this is the feature you are trying to use https://specs.openstack.org/openstack/nova-specs/specs/rocky/implemented/neutron-new-port-binding-api.html | |
| 23:34:52 | sean-k-mooney | i did not think this required post-copy but let me double check | |
| 23:35:17 | abaindur | well thats why we were considering trying out post-copy - to see if it speeds up when nova makes the port binding call | |
| 23:35:30 | sean-k-mooney | ok so yes if you want the quick setup we are waiting for VIR_DOMAIN_EVENT_SUSPENDED_POSTCOPY | |
| 23:35:43 | abaindur | post-copy seems to trigger that call based on VIR_DOMAIN_EVENT states | |
| 23:36:14 | abaindur | pre-copy waits for that _post_live_migration() on the host to invoke network_api.migrate_instance_start(), which seems to take a while for us | |
| 23:36:29 | sean-k-mooney | that will allow us to activate the port bidning from the souce earlier then _post_live_migration | |
| 23:37:13 | abaindur | Right, thats why we will try post-copy mode. But was wondering if the downtime/delay we are seeing with pre-copy is expected or unavoidable? | |
| 23:37:19 | sean-k-mooney | abaindur: ya so it is a littl strange that your _post_live_migration function completion is os long | |
| 23:37:39 | sean-k-mooney | i would not expect _post_live_migration to take multiple seconds | |
| 23:38:41 | abaindur | what are downsides to post copy besides that VM needs to be rebooted if theres a live migration error? | |
| 23:39:06 | abaindur | and page faults may slow down the VM as memory needs to be copied over the network? | |
| 23:39:17 | sean-k-mooney | that is the main one. if there is a network outage while its still in post copy phase then the vm will crash | |
| 23:39:35 | sean-k-mooney | yes page falts acroos the network might beut all write happen locally | |
| 23:39:47 | sean-k-mooney | so the vm will only pause if it need to read un copied data | |
| 23:40:05 | sean-k-mooney | and once its copied local update to that will happen to the dest memmory | |
| 23:40:19 | sean-k-mooney | as you pointed out we are activating the port here https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L7005 | |
| 23:40:54 | sean-k-mooney | which happen near the star of the function so the dely is likely related to cinder performance | |
| 23:41:10 | sean-k-mooney | abaindur: have you tried live migrating vms that dont have cinder volumes | |
| 23:41:28 | abaindur | yea, we tried VMs both volume and ephemeral based | |
| 23:41:42 | sean-k-mooney | did you see the same delay? | |
| 23:42:03 | abaindur | pretty much | |
| 23:42:24 | abaindur | timed the volume code with some logs of our own, heres what we observed: | |
| 23:42:36 | abaindur | 1.913 seconds for _get_instance_block_device_info and self.driver.post_live_migration | |
| 23:42:45 | abaindur | about 0.4 sec for self.driver.get_volume_connector(instance) | |
| 23:42:51 | abaindur | 2.659 seconds for self.volume_api.terminate_connection() | |
| 23:42:58 | abaindur | 3.28 seconds for network_info = self.network_api.get_instance_nw_info(ctxt, instance) | |
| 23:43:03 | abaindur | 5.019 seconds for self._notify_about_instance_usage(ctxt, instance, "live_migration._post.start", network_info=network_info) | |
| 23:43:16 | abaindur | another almost 5 seconds nova spent just making the port binding activate API call, seems to be spending time in keystone and oslo_concurrency.lockutils code | |
| 23:43:25 | sean-k-mooney | is that absolute time of time for each function | |
| 23:43:44 | abaindur | yea, we just added logs throughout that post_live_migration() function | |
| 23:43:56 | abaindur | before/after each of those calls to see what was taking so long | |
| 23:44:01 | sean-k-mooney | ok so i subtrac those numebr to get the time for each | |
| 23:44:07 | sean-k-mooney | that is still very slow | |
| 23:44:30 | abaindur | for example, in one live migration, we say: VM Paused at 25:06.192 | |
| 23:44:39 | sean-k-mooney | abaindur: are you using memcache for you keysontone auth tokens | |
| 23:45:32 | abaindur | by time we saw nova-compute make the port binding call, it was at: 35:24.694 | |
| 23:46:20 | abaindur | VM Paused at 35:06.192 * | |
| 23:46:49 | sean-k-mooney | abaindur: can you check your nova.conf and see if you have https://zuul.opendev.org/t/openstack/build/dcde79801a624c25b195a46ead7af562/log/controller/logs/etc/nova/nova-cpu_conf.txt#62-68 | |
| 23:49:04 | sean-k-mooney | also 10 seconds to bind the port in precopy mode is too hight so there is something else hurting performance which is why im suspecign you do not have caching of keysotne configure correctly. | |
| 23:52:47 | abaindur | Ok no, memcache_servers is not set... | |
| 23:52:58 | abaindur | this is for nova compute on the hypervisor side right? | |
| 23:53:44 | sean-k-mooney | https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L6982-L7008 could be safely moved to https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L6939 by the way and in the libvirt case https://github.com/openstack/nova/blob/stable/rocky/nova/compute/manager.py#L6933 woudl be fine too. | |
| 23:53:57 | sean-k-mooney | am it will be used both on the contoler and computes | |
| 23:54:13 | sean-k-mooney | so you are missing | |
| 23:54:16 | sean-k-mooney | [keystone_authtoken] | |
| 23:54:18 | sean-k-mooney | memcached_servers = localhost:11211 | |
| 23:54:25 | sean-k-mooney | or well your actull memcache servers | |
| 23:54:45 | abaindur | yeah, I dont see that config opt ever ok | |
| 23:54:49 | sean-k-mooney | this will be used to cach auth tokens for every api call we make | |
| 23:55:16 | abaindur | i dont see it ever set* | |
| 23:58:21 | sean-k-mooney | abaindur: so at least on the contoler side it has a significnat impact on the api | |
| 23:58:25 | openstack | Launchpad bug 1836642 in neutron "Metadata responses are very slow sometimes" [High,Incomplete] - Assigned to Slawek Kaplonski (slaweq) | |
| 23:58:25 | sean-k-mooney | https://bugs.launchpad.net/nova/+bug/1836642 | |
| 23:58:53 | sean-k-mooney | we adress this porblem in the gate by truning on caching with https://github.com/openstack/devstack/commit/d33cdd01f83b891b010e0fd238f1816910f3fd77 | |
| 23:59:18 | abaindur | I dont see it on controller either | |
| 23:59:25 | sean-k-mooney | i am not sure if i tis use dby the compute node but i think it will be whenever it is calling cinder neutron or placment | |
| 23:59:35 | sean-k-mooney | abaindur: its optional | |
| 23:59:49 | sean-k-mooney | but it improves perfromacne alot | |
| #openstack-nova - 2020-04-21 | |||
| 00:00:01 | abaindur | so for pre-copy, you are suggesting to try memcache for keystone tokens? | |
| 00:00:29 | sean-k-mooney | ya but im not saying dont try enableing post-copy | |
| 00:00:48 | sean-k-mooney | im just sugging that memcache might impove the performace enough to not need it | |
| 00:00:54 | sean-k-mooney | i woudl test both | |
| 00:01:12 | sean-k-mooney | abaindur: how did you deploy openstack by the way | |
| 00:01:23 | abaindur | thanks, yea we'll probably try both options then to see which leads to least downtime | |
| 00:01:51 | sean-k-mooney | for both options is basically just a compute agent restart and cofig update | |
| 00:03:24 | openstack | Launchpad bug 1836642 in neutron "Metadata responses are very slow sometimes" [High,Incomplete] - Assigned to Slawek Kaplonski (slaweq) | |
| 00:03:24 | sean-k-mooney | abaindur: at least in the case of https://bugs.launchpad.net/nova/+bug/1836642 we were seeing edgcaces wher ethe metadta api respoce could take upwards of 12 - 16 seconds and that went away when we enabeld the cache | |
| 00:05:00 | sean-k-mooney | abaindur: although to be clear we enabel both the cache section and the memcahced_server in the keystone_authoken section | |
| 00:05:18 | sean-k-mooney | so all of the highlight section is how we adressed the isseu https://zuul.opendev.org/t/openstack/build/dcde79801a624c25b195a46ead7af562/log/controller/logs/etc/nova/nova-cpu_conf.txt#62-68 | |
| 00:09:27 | sean-k-mooney | abaindur: https://docs.openstack.org/keystonemiddleware/latest/middlewarearchitecture.html#improving-response-time might be of interst | |
| 00:11:30 | sean-k-mooney | i think that might only be relevent to the apis service however and might not apply to when we use the keystone auth client to talk to otehr apis but im not sure baout that. anyway its late here so im going to go o/ | |
| 00:11:58 | abaindur | sean-k-mooney: oh wait, we have memcached_servers set in keystone_authtoken | |
| 00:12:05 | abaindur | but we dont have a [cache] section with the other configs | |
| 00:12:37 | sean-k-mooney | ah the cache section is novas own internal cache config | |
| 00:13:07 | sean-k-mooney | so in the metadata api case it is what allows cache copies fo the metadata to be shareed between processes | |
| 00:14:00 | sean-k-mooney | i think your best path forward in that cae is likely your original one of enabling post copy. you might also want o consider auto convergence | |
| 00:27:50 | abaindur | ok thanks for the help! will update here later if i find out more | |
| 00:42:47 | openstackgerrit | Merged openstack/nova master: Allocate mdevs when resizing or reverting resize https://review.opendev.org/712741 | |