Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2019-07-16
10:55:47 openstackgerrit Merged openstack/nova master: Add Python 3 Train unit tests https://review.opendev.org/669437
10:58:03 sean-k-mooney slaweq: it look like that was the first request on that worker thread and it had to initalise the db connection andproably some other setup stuff
10:59:42 sean-k-mooney slaweq: we can see the request is recived here http://logs.openstack.org/09/666409/7/check/tempest-full/08f4c53/controller/logs/screen-n-api-meta.txt.gz#_Jul_11_23_43_00_523076
11:00:32 slaweq sean-k-mooney: yes, and response is send here: http://logs.openstack.org/09/666409/7/check/tempest-full/08f4c53/controller/logs/screen-n-api-meta.txt.gz#_Jul_11_23_43_16_704979
11:00:43 slaweq it took 16 seconds to send it back
11:01:15 slaweq after 10 seconds this "cloud-init" like script in cirros is failing and instance don't have SSH key configured thus test fails :/
11:01:51 sean-k-mooney yes but if you look at the pids it was setting up the db connection on pid 9232 which is the pid that serviced the request
11:02:17 slaweq sean-k-mooney: and what is strange for me, is that only this one request was so slow
11:02:20 sean-k-mooney so im guessing it was delayed becasue the api worker hadn to do some intal setup
11:02:39 slaweq why all other requests around this are much faster?
11:03:17 sean-k-mooney becasue they dont have to inisllise the wsgi app and set up the db connections
11:03:23 slaweq sean-k-mooney: but don't You think it is bug if nova needs sometimes 16 seconds to send public-key?
11:03:30 sean-k-mooney they can reuse all the work that has been done
11:04:12 sean-k-mooney i dont think it actully too 16 second i think it was waiting for the database to return with the reponce
11:04:32 slaweq from user (VM) PoV it was 16 seconds
11:04:58 sean-k-mooney sure
11:05:32 sean-k-mooney but as i said it look like this is because its the frist api request recived by that worker
11:06:28 sean-k-mooney 16 seconds is not really that un resonable given the load that the gate vms are under. we can see if there is a way to speed it up but i dont think this would be an issue in production
11:09:04 openstackgerrit Lee Yarwood proposed openstack/nova master: Get rid of args to RBDDriver.__init__() https://review.opendev.org/668564
11:09:37 slaweq sean-k-mooney: the problem is that this is an issue in the gate :/
11:10:11 openstackgerrit Balazs Gibizer proposed openstack/nova master: Move consts from neutronv2/api to constants module https://review.opendev.org/668945
11:10:21 sean-k-mooney slaweq: yep which we may not be able to fix in nova. im goint to look at the other logs and then ill look at the code
11:10:51 sean-k-mooney but its like saying the ovs neutorn agenet does not wire up new port imediatly after teh agent is restart
11:10:52 slaweq sean-k-mooney: thx
11:11:28 openstackgerrit Balazs Gibizer proposed openstack/nova master: Translatable output strings in heal allocation https://review.opendev.org/668925
11:11:56 sean-k-mooney we know it take a whlie for it to recompute everything because it has a lot of work to do on start up. maybe we tweak something or have devstack ping the metadta api
11:12:23 sean-k-mooney e.g. before tempest runs to make sure this setup is done before a test hits it
11:12:45 slaweq sean-k-mooney: or other "gate only workaround" could be to patch cirros image and retry those calls if it fails first time
11:14:16 cdent "gate only workaround"--
11:19:26 sean-k-mooney looking at the logs more closely the reponces that are 2ms are all cached
11:21:05 sean-k-mooney uncached responces for new intanstances are between 300-1000ms generally with the 16000 ms and similar long resonces also doing addtional work
11:23:05 sean-k-mooney by addtional work i mean it has to aquire a lock and call nova.context.get_or_set_cached_cell_and_set_connections before it then generates the metadata
11:23:21 sean-k-mooney or in the case of the first request also set up the db connection
11:25:30 sean-k-mooney ok so when its not cached it has to call this
11:25:32 sean-k-mooney https://github.com/openstack/nova/blob/af4cd78e8537d8f0933e30598066cedac5844866/nova/context.py#L355-L375
11:26:15 openstackgerrit Balazs Gibizer proposed openstack/nova master: Use neutron contants in cmd/manage.py https://review.opendev.org/668946
11:26:15 openstackgerrit Balazs Gibizer proposed openstack/nova master: Add 'resource_request' to neutronv2/constants https://review.opendev.org/668947
11:26:22 sean-k-mooney which set up both the db connection and rabbitmq connection if its not already cached
11:35:46 sean-k-mooney ok so that is invoked when teh context target_cell context manager is used to lookup the instace by its uuid here https://github.com/openstack/nova/blob/master/nova/api/metadata/base.py#L680
11:35:51 slaweq sean-k-mooney: thx for looking into this
11:37:30 openstackgerrit Balazs Gibizer proposed openstack/nova master: Use the safe get_binding_profile https://review.opendev.org/669817
11:49:48 gibi efried: if you have time, could you look back to https://review.opendev.org/#/c/666857 ?
11:55:34 sean-k-mooney slaweq: im not 100% certin but the metadata api request that took 16 seconds may have been waiting on neutron for 12 second to respond with the security groups for the instance http://logs.openstack.org/09/666409/7/check/tempest-full/08f4c53/controller/logs/screen-q-svc.txt.gz#_Jul_11_23_43_16_660751
12:01:29 sean-k-mooney slaweq: actully the device id of the port matches the instance id of the metadata request so yes its was waiting for neuton to return the security group info
12:02:05 sean-k-mooney when we are building the metata data we call neutron to get the security group info here https://github.com/openstack/nova/blob/master/nova/api/metadata/base.py#L145
12:02:19 sean-k-mooney which does this https://github.com/openstack/nova/blob/46a3bcd80b41e99ec4923c7cf3d0f8dd8505e97c/nova/network/security_group/neutron_driver.py#L374-L409
12:02:58 sean-k-mooney we list the ports associated with the server which we can see in the neutorn log here http://logs.openstack.org/09/666409/7/check/tempest-full/08f4c53/controller/logs/screen-q-svc.txt.gz#_Jul_11_23_43_04_463505
12:03:48 sean-k-mooney then we retrive the securtiy group info which takes 12 seconds http://logs.openstack.org/09/666409/7/check/tempest-full/08f4c53/controller/logs/screen-q-svc.txt.gz#_Jul_11_23_43_16_660751
12:04:08 sean-k-mooney it starts here http://logs.openstack.org/09/666409/7/check/tempest-full/08f4c53/controller/logs/screen-q-svc.txt.gz#_Jul_11_23_43_04_575879
12:05:11 sean-k-mooney slaweq: what does "Synchronizing usage tracker for tenant" mean in the context of security groups?
12:07:39 openstackgerrit Balazs Gibizer proposed openstack/nova master: Defaults missing group_policy to 'none' https://review.opendev.org/657796
12:26:56 slaweq sean-k-mooney: let me look at this now
12:31:23 kashyap aspiers: Hi, if you have a SUSE system near by, can you please check if any of the OVMF/EDK2 packages provide this file: /usr/share/OVMF/OVMF_CODE.fd
12:34:24 slaweq sean-k-mooney: it looks that this "Synchronizing usage tracker for tenant.." is done here: https://github.com/openstack/neutron/blob/master/neutron/quota/resource.py#L245 and it counts number of security groups in db and update quota usage in db for this tenant
12:34:37 slaweq sean-k-mooney: I will investigate this more, thx a lot for help
12:35:04 sean-k-mooney im updating the bug and tyring to see if its the same cause for other cases
12:35:15 slaweq sean-k-mooney: thx
12:35:56 sean-k-mooney i am not sure its the same issue in all cases but i did see a another 12 second wait to get netwrok info in another case
12:36:15 sean-k-mooney im currently confirming its coming form a metadta build request
12:37:07 artom lyarwood, heya, could you hit https://review.opendev.org/#/q/topic:bug/1832028+(status:open+OR+status:merged) ?
12:37:25 artom And we'd need to find another stable core, with mriedem having a much earned PTO
12:52:18 lyarwood artom: just hit the stable/stein one, quick open question around testing
12:52:58 lyarwood artom: I'm not sure if we need another DMN testing change in Neutron on stable/stein for this or if everything in Nova stable/stein is already enough
12:54:53 openstackgerrit Matthew Booth proposed openstack/nova master: Failing unit test for bug 1836212 https://review.opendev.org/671023
12:54:54 openstack bug 1836212 in OpenStack Compute (nova) "libvirt: Failure to recover from failed detach" [Undecided,New] https://launchpad.net/bugs/1836212
12:55:04 efried gibi: on it
12:55:11 efried Anyone know where cfriesen has been lately?
13:12:53 efried gibi: are you still here?
13:17:07 kashyap efried: I was wondering, too.
13:17:12 kashyap Probably buried in downstream stuff
13:17:58 efried kashyap: Do you know anything about the libvirt patches to make vTPM more secure?
13:18:22 kashyap efried: I do, peripherially. And funny you ask!
13:18:40 kashyap Just today I was browsing that vTPM thread on upstream libvirt list
13:19:12 kashyap The patch series is at v5, and almost ready to be merged
13:19:18 efried LibVirt RFE: https://bugzilla.redhat.com/show_bug.cgi?id=1728030
13:19:18 efried RH has already written a patch https://www.redhat.com/archives/libvir-list/2019-July/msg00584.html
13:19:18 openstack bugzilla.redhat.com bug 1728030 in libvirt "RFE: Add encryption of TPM emulator state" [Unspecified,New] - Assigned to libvirt-maint
13:19:22 kashyap efried: https://www.redhat.com/archives/libvir-list/2019-July/msg00854.html
13:19:31 kashyap "PATCH v5 00/20] Add support for vTPM state encryption
13:19:32 kashyap "
13:19:43 efried cool, I don't know how to read any of that, so "almost ready to be merged" is a good bit of info.
13:20:06 kashyap It has gone through a good few rounds of feedback from long-time reviewers upstream
13:20:12 efried when that happens, will there need to be any special affordance in the nova design to enable it?
13:20:31 efried like, do we have to (conditionally based on available libvirt version) do something different to the xml?
13:20:41 kashyap efried: Probably the config classes and XML exposure, and the relevant calls in libvirt/driver.py?
13:20:59 efried I guess at the very least we would have to expose a trait saying that "more secure vTPM is available here"
13:21:16 kashyap Right, on the version conditionals
13:21:52 efried But someone needs to be working on the code in the first place. It hasn't been touched since the PTG.
13:22:28 kashyap efried: Yeah, if the author has gone AWOL, then probably "punt it to backlog"?
13:22:36 kashyap When they come back, it can be revived.
13:22:38 efried no can do
13:22:53 kashyap Sorry, what do you mean?
13:22:55 efried more likely "find new owner asap"
13:22:58 kashyap Ah
13:23:03 efried downstream pressure
13:23:14 kashyap Ah-ha, nod.
13:23:41 kashyap It is a useful, self-contained solution -- for those who want it.
13:27:05 kashyap efried: You do know that the core vTPM stuff is merged in upstream libvirt, yeah?
13:27:22 kashyap (The series linked above is for the vTPM state being ecrypted)
13:27:24 efried kashyap: Yeah

Earlier   Later