On 10/31/2019 4:15 PM, Slawek Kaplonski wrote:

...

1.http://status.openstack.org/elastic-recheck/index.html#1763070

This has resurfaced and I'm not sure why, nor do I think we ever had a great handle on what is causing this or how to work around it so if anyone has new ideas please chip in. I think that this is "just" some slowdown of node on which job is running. I noticed it too in some neutron jobs and I checked some. It seems that one API request is processed for very long time. For example in one of fresh examples: https://13cf3dd11b8f009809dc-97cb3b32849366f5bed744685e46b266.ssl.cf5.rackcd... it was request to nova which caused very long time:

Oct 31 16:55:08.632162 ubuntu-bionic-inap-mtl01-0012620879devstack@n-api.service[7191]: INFO nova.api.openstack.requestlog [None req-275af2df-bd4e-4e64-b46e-6582e8de5148 tempest-ServerDiskConfigTestJSON-1598674508 tempest-ServerDiskConfigTestJSON-1598674508] 198.72.124.104 "POST /compute/v2.1/servers/d15d2033-b29b-44f7-b619-ed7ef83fe477/action" status: 500 len: 216 microversion: 2.1 time: 161.951140

That's really interesting, I hadn't noticed the MessagingTimeout in n-api linked to this. I dug into that one and it's really odd, but there is one known and one unknown issue here. The known issue is resize/cold migrate is synchronous through API, conductor and scheduler while picking a host and then we finally return to the API caller when we RPC cast to the selected destination host. If we RPC cast from API to conductor we'd avoid that MessagingTimeout issue. The unknown weirdness that made this fail is it took ~3 minutes to move allocations from the instance to the migration record. We hit conductor about here: Oct 31 16:52:24.300732 ubuntu-bionic-inap-mtl01-0012620879 nova-conductor[14891]: DEBUG nova.conductor.tasks.migrate [None req-275af2df-bd4e-4e64-b46e-6582e8de5148 tempest-ServerDiskConfigTestJSON-1598674508 tempest-ServerDiskConfigTestJSON-1598674508] [instance: d15d2033-b29b-44f7-b619-ed7ef83fe477] Requesting cell 374faad6-7a6f-40c7-b2f4-9138e0dde5d5(cell1) while migrating {{(pid=16132) _restrict_request_spec_to_cell /opt/stack/nova/nova/conductor/tasks/migrate.py:172}} And then finally get the message that we moved allocations prior to scheduling: Oct 31 16:55:08.634009 ubuntu-bionic-inap-mtl01-0012620879 nova-conductor[14891]: DEBUG nova.conductor.tasks.migrate [None req-275af2df-bd4e-4e64-b46e-6582e8de5148 tempest-ServerDiskConfigTestJSON-1598674508 tempest-ServerDiskConfigTestJSON-1598674508] Created allocations for migration 86ccf6f2-a2b0-4ae0-9c31-8bbdac4ceda9 on eccff5f8-3175-4170-b87e-cb556865fde0 {{(pid=16132) replace_allocation_with_migration /opt/stack/nova/nova/conductor/tasks/migrate.py:86}} After that we call the scheduler to find a host and that only takes about 1 second. That POST /allocations call to placement shouldn't be taking around 3 minutes so something crazy is going on there. If I'm reading the placement log correctly, that POST starts here: Oct 31 16:52:24.721346 ubuntu-bionic-inap-mtl01-0012620879 devstack@placement-api.service[8591]: DEBUG placement.requestlog [req-275af2df-bd4e-4e64-b46e-6582e8de5148 req-295f7350-2f0b-4f85-8cdf-d76801637221 None None] Starting request: 198.72.124.104 "POST /placement/allocations" {{(pid=8593) __call__ /opt/stack/placement/placement/requestlog.py:61}} And returns here: Oct 31 16:55:08.629708 ubuntu-bionic-inap-mtl01-0012620879 devstack@placement-api.service[8591]: DEBUG placement.handlers.allocation [req-275af2df-bd4e-4e64-b46e-6582e8de5148 req-295f7350-2f0b-4f85-8cdf-d76801637221 service placement] Successfully wrote allocations [<placement.objects.allocation.Allocation object at 0x7f023c9bcfd0>, <placement.objects.allocation.Allocation object at 0x7f023c9bc6d8>, <placement.objects.allocation.Allocation object at 0x7f023c9bcc18>, <placement.objects.allocation.Allocation object at 0x7f023c9eb7f0>, <placement.objects.allocation.Allocation object at 0x7f023c9ebdd8>, <placement.objects.allocation.Allocation object at 0x7f023c9eb630>] {{(pid=8593) _create_allocations /opt/stack/placement/placement/handlers/allocation.py:524}} Oct 31 16:55:08.629708 ubuntu-bionic-inap-mtl01-0012620879 devstack@placement-api.service[8591]: INFO placement.requestlog [req-275af2df-bd4e-4e64-b46e-6582e8de5148 req-295f7350-2f0b-4f85-8cdf-d76801637221 service placement] 198.72.124.104 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 Oct 31 16:55:08.629708 ubuntu-bionic-inap-mtl01-0012620879 devstack@placement-api.service[8591]: [pid: 8593|app: 0|req: 304/617] 198.72.124.104 () {72 vars in 1478 bytes} [Thu Oct 31 16:52:24 2019] POST /placement/allocations => generated 0 bytes in 163883 msecs (HTTP/1.1 204) 5 headers in 199 bytes (1 switches on core 0) I know Chris Dent has done a lot of profiling on placement recently but I'm not sure if much has been done around profiling the POST /allocations call to move allocations from one consumer to another. That also looks like some kind of anomaly because looking at that log at other POST /allocations calls, many take only 50-70 milliseconds. I wonder if there is a potential lock somewhere in placement slowing things down in that path. -- Thanks, Matt

On Thu, 31 Oct 2019, Matt Riedemann wrote:

After that we call the scheduler to find a host and that only takes about 1 second. That POST /allocations call to placement shouldn't be taking around 3 minutes so something crazy is going on there.

Yeah, this is indeed weird and wrong. There are two obvious ways, in the placement code, that _set_allocations (which underlies all the allocation changing requests) could be slowed down: * If the resource provider's generation has changed during the request, because something else is also writing allocations at the same time, there will be up to 10 retries, server-side. * For each of those tries, there's (apparently) a chance of a db deadlock, because the method is guarded by a retry on deadlock. We added that in a long long time ago. However, if the generation retry was happening, it would show up in the logs as "Retrying allocations write on resource provider". And if we were getting deadlock we ought to see "Performing DB retry for function". There could be other non-obvious things, but more data required... (more)

Oct 31 16:52:24.721346 ubuntu-bionic-inap-mtl01-0012620879 devstack@placement-api.service[8591]: DEBUG placement.requestlog [req-275af2df-bd4e-4e64-b46e-6582e8de5148 req-295f7350-2f0b-4f85-8cdf-d76801637221 None None] Starting request: 198.72.124.104 "POST /placement/allocations" {{(pid=8593) __call__ /opt/stack/placement/placement/requestlog.py:61}}

We start the requestlog at the very beginning of the request so there are a few steps between here and the actual data interaction, so another possible angle of investigation here is that keystonemiddleware was being slow to validate a token for some reason.

I know Chris Dent has done a lot of profiling on placement recently but I'm not sure if much has been done around profiling the POST /allocations call to move allocations from one consumer to another.

You're right that little was done to profile allocations, mostly because initial experiments showed that it was fast and get /a_c was slow. In the fullness of time I probably would have moved on to allocations but reality intervened. What's probably most important is evaluating allocation writes to the same set of several resource providers under high concurrency. However it doesn't seem like that is what is happening in this case (otherwise I'd expect to see more evidence in the logs). Instead it's "just being slow" which could be any of: * something in the auth process (which if other services are also being slow could be a unifying thing) * the database server having a sad (do we keep a slow query log?) * the vm/vms has/have a noisy neighbor Do we know anything about cpu and io stats during the slow period? We've (sorry, let me rephrase, I've) known for the entire 5.5 years I've been involved in OpenStack that the CI resources are way over-subscribed and controller nodes in the wild are typically way under-specified. Yes, our code should be robust in the face of that, but... Of course, I could be totally wrong, there could be something flat out wrong in the placement code, but if that were the case I'd expect (like Matt did) to see it more often. -- Chris Dent ٩◔̯◔۶ https://anticdent.org/ freenode: cdent

On 11/1/2019 8:30 AM, Matt Riedemann wrote:

Looks like around the time of slowness mysqld is the top consuming process which is probably not surprising.

Oh I also see this in the mysql error log [1] around the time of the slow period, right after things pick back up: 2019-10-31T16:55:08.603773Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 161281ms. The settings might not be optimal. (flushed=201 and evicted=0, during the time.) So obviously something is going very wrong with mysql (or the node in general) during that time. [1] https://13cf3dd11b8f009809dc-97cb3b32849366f5bed744685e46b266.ssl.cf5.rackcd... -- Thanks, Matt

On 11/1/2019 9:55 AM, Clark Boylan wrote:

OVH controls the disk IOPs that we get pretty aggressively as well. Possible it is an IO thing?

Yeah, so looking at the dstat output in that graph (thanks for pointing out that site, really nice) we basically have 0 I/O from 16:53 to 16:55, so uh, that's probably not good. -- Thanks, Matt

On Mon, Nov 4, 2019, at 7:37 PM, Chris Dent wrote:

On Fri, 1 Nov 2019, Matt Riedemann wrote:

...

On 11/1/2019 9:55 AM, Clark Boylan wrote:

...

OVH controls the disk IOPs that we get pretty aggressively as well. Possible it is an IO thing?

Yeah, so looking at the dstat output in that graph (thanks for pointing out that site, really nice) we basically have 0 I/O from 16:53 to 16:55, so uh, that's probably not good.

What happens in a case like this? Is there an official procedure for "hey, can you give is more IO?" or (if that's not an option) "can you give us less CPU?". Is that something that is automated, is is something that is monitored and alarming? "INAP ran out of IO X times in the last N hours, light the beacons!"

Typically we try to work with the clouds to properly root cause the issue. Then from there we can figure out what the best fix may be. They are running our software after all and there is a good chance the problems are in openstack. I'm in shanghai at the moment but if others want to reach out feel free. benj_ and mgagne are at inap and amorin has been helpful at ovh. The test node logs include a hostid in them somewhere which an be used to identify hypervisors if necessary. Clark

On 11/4/19 16:58, Clark Boylan wrote:

On Mon, Nov 4, 2019, at 7:37 PM, Chris Dent wrote:

...

On Fri, 1 Nov 2019, Matt Riedemann wrote:

...

On 11/1/2019 9:55 AM, Clark Boylan wrote:

...

OVH controls the disk IOPs that we get pretty aggressively as well. Possible it is an IO thing?

Yeah, so looking at the dstat output in that graph (thanks for pointing out that site, really nice) we basically have 0 I/O from 16:53 to 16:55, so uh, that's probably not good.

What happens in a case like this? Is there an official procedure for "hey, can you give is more IO?" or (if that's not an option) "can you give us less CPU?". Is that something that is automated, is is something that is monitored and alarming? "INAP ran out of IO X times in the last N hours, light the beacons!"

Typically we try to work with the clouds to properly root cause the issue. Then from there we can figure out what the best fix may be. They are running our software after all and there is a good chance the problems are in openstack.

I'm in shanghai at the moment but if others want to reach out feel free. benj_ and mgagne are at inap and amorin has been helpful at ovh. The test node logs include a hostid in them somewhere which an be used to identify hypervisors if necessary.

Just wanted to throw this out there to the ML in case anyone has any thoughts: Since we know that I/O is overloaded in these cases, would it make any sense to have infra/tempest use a flavor which sets disk I/O quotas [1] to help prevent any one process from getting starved out? I agree that properly troubleshooting the root cause is necessary and maybe adding limits would not be desired for concern of it potentially hiding issues. -melanie [1] https://docs.openstack.org/nova/latest/user/flavors.html#extra-specs-disk-tu...

On 12/20/2019 11:47 AM, Matt Riedemann wrote:

Dredging this back up after discussing with Clark in IRC today. I've posted a patch to disable c-bak and etcd3 in grenade jobs [1]. The hope is this will alleviate some pressure on OVH nodes where iops are restricted. We aren't even effectively doing anything with c-bak and etcd3 in grenade jobs so this should not be controversial.

[1] https://review.opendev.org/#/c/700214/

Actually doing it in the grenade repo doesn't work because of how devstack-gate generates the enabled services list for legacy jobs so I've got a series in devstack-gate that delivers the goods. https://review.opendev.org/#/c/700233/ -- Thanks, Matt

On 10/31/2019 4:15 PM, Slawek Kaplonski wrote:

...

3. CirrOS guest SSH issues

There are several (some might be duplicates):

http://status.openstack.org/elastic-recheck/index.html#1848078 This one is I think the same as we have reported in https://bugs.launchpad.net/neutron/+bug/1850557

Basically we noticed issues with dhcp after resize/migration/shelve of instance but I didn't have time to investigate it yet.

Hmm, https://review.opendev.org/#/c/670591/ is new to devstack in Train and was backported to stable/stein. I wonder if that is too aggressive and is causing issues with operations where the guest is stopped and started, though for resize/migrate/shelve/unshelve the guest is destroyed on one host and re-spawned on another, so I would think that having a graceful shutdown for the guest wouldn't matter in those cases, unless it has to do with leaving the guest "dirty" somehow before transferring the root disk / creating a snapshot (in the case of shelve). Maybe we should bump that back up to 10 seconds? -- Thanks, Matt

Hi,

On 1 Dec 2019, at 11:44, Slawek Kaplonski <skaplons@redhat.com> wrote:

Hi,

...

On 31 Oct 2019, at 23:03, Matt Riedemann <mriedemos@gmail.com> wrote:

On 10/31/2019 4:15 PM, Slawek Kaplonski wrote:

...

...

3. CirrOS guest SSH issues

There are several (some might be duplicates):

http://status.openstack.org/elastic-recheck/index.html#1848078 This one is I think the same as we have reported in https://bugs.launchpad.net/neutron/+bug/1850557 Basically we noticed issues with dhcp after resize/migration/shelve of instance but I didn't have time to investigate it yet.

Hmm, https://review.opendev.org/#/c/670591/ is new to devstack in Train and was backported to stable/stein. I wonder if that is too aggressive and is causing issues with operations where the guest is stopped and started, though for resize/migrate/shelve/unshelve the guest is destroyed on one host and re-spawned on another, so I would think that having a graceful shutdown for the guest wouldn't matter in those cases, unless it has to do with leaving the guest "dirty" somehow before transferring the root disk / creating a snapshot (in the case of shelve). Maybe we should bump that back up to 10 seconds?

I finally spent some time on investigating this issue. I was able to reproduce it locally and I found that the problem is in openvswitch firewall. All is described in [1]. I just pushed patch which should fix this. It’s in [2].

My patch is now merged so I hope we will not see this issue with SSH in resize/shelve tests anymore.

[1] https://bugs.launchpad.net/neutron/+bug/1850557 [2] https://review.opendev.org/696794

...

--

Thanks,

Matt

— Slawek Kaplonski Senior software engineer Red Hat

— Slawek Kaplonski Senior software engineer Red Hat

Hi, On Tue, Dec 03, 2019 at 01:53:04PM +0000, Sean Mooney wrote:

On Thu, Oct 31, 2019 at 3:29 PM Matt Riedemann <mriedemos@gmail.com> wrote:

...

Things are great! Surprise! I just wanted to let everyone know. Later! . . . . . Now that you've been tricked, on Halloween no less, I'm here to tell you that things suck right now. This is your periodic digest of issues. Grab some fun-sized candy bars and read on.

I think right now we have three major issues.

1. http://status.openstack.org/elastic-recheck/index.html#1763070

This has resurfaced and I'm not sure why, nor do I think we ever had a great handle on what is causing this or how to work around it so if anyone has new ideas please chip in.

the only theory i have on that is in the absense of any other indication we could be running out of entorpy in the vm which can lead to https connections failing. we might want to consider enabling the virtio random number generator in the gate vms. https://github.com/openstack/glance/blob/master/etc/metadefs/compute-libvirt... this need to be enabled in the flavours too but low entroy can cass ssl connection to fail https://major.io/2007/07/01/check-available-entropy-in-linux/

You may be right with lack of entropy is culprit in some issues. E.g. here: https://zuul.opendev.org/t/openstack/build/edcf837457a741abb752693723319b15/... it took 120 seconds to Initialize random number generator on guest VM and because of that network wasn't configured properly and test failed.

...

2. http://status.openstack.org/elastic-recheck/index.html#1844929

I've done some digging into this one and my notes are in the bug report. It mostly affects grenade jobs but is not entirely restricted to grenade jobs. It's also mostly on OVH and FortNebula nodes but not totally.

From looking at the mysql logs in the grenade jobs, mysqld is (re)started three times. I think (1) for initial package install, (2) for stacking devstack on the old side, and (3) for stacking devstack on the new side. After the last restart, there are a lot of aborted connection messages in the msyql error log. It's around then that grenade is running post-upgrade smoke tests to create a server and the nova-scheduler times out communicating with the nova_cell1 database.

I have a few patches up to grenade/devstack [1] to try some things and get more msyql logs but so far they aren't really helpful. We need someone with some more mysql debugging experience to help here, maybe zzzeek or mordred?

3. CirrOS guest SSH issues

There are several (some might be duplicates):

http://status.openstack.org/elastic-recheck/index.html#1848078 http://status.openstack.org/elastic-recheck/index.html#1808010 (most hits) http://status.openstack.org/elastic-recheck/index.html#1463631 http://status.openstack.org/elastic-recheck/index.html#1849857 http://status.openstack.org/elastic-recheck/index.html#1737039 http://status.openstack.org/elastic-recheck/index.html#1840355 http://status.openstack.org/elastic-recheck/index.html#1843610

A few notes here.

a) We're still using CirrOS 0.4.0 since Stein:

https://review.opendev.org/#/c/521825/

And that image was published nearly 2 years ago and there are no newer versions on the CirrOS download site so we can't try a newer image to see if that fixes things.

b) Some of the issues above are related to running out of disk in the guest. I'm not sure what is causing that, but I have posted a devstack patch that is related:

https://review.opendev.org/#/c/690991

tl;dr before Stein the tempest flavors we used had disk=0 so nova would fit the root disk to the size of the image. Since Stein the tempest flavors specify root disk size (1GiB for the CirrOS images). My patch pads an extra 1GiB to the root disk on the tempest flavors. One side effect of that is the volumes tempest creates will go from 1GiB to 2GiB which could be a problem if a lot of tempest volume tests run at the same time, though we do have a volume group size of 24GB in gate runs so I think we're OK for now. I'm not sure my patch would help, but it's an idea.

As for the other key generation and dhcp lease failures, I don't know what to do about those.We need more eyes on these issues to generate

so the ssh key generation issue may also be down to entorpoy. i have not looked at those specific failueres but i did note in some failed test in the past the we printed the kernel entropy in the guest and it was like 36 so some other very low number(it should be in the hundreds). if we have low entropy key generation will take a long time. https://wiki.debian.org/BoottimeEntropyStarvation

...

some ideas or see if we're doing something wrong in our tests, e.g. generating too much data for the config drive? Not using config drive in some cases? Metadata API server is too slow (note we cache the metadata since [2])? Other ideas on injecting logs for debug?

[1] https://review.opendev.org/#/q/topic:bug/1844929+status:open [2] https://review.opendev.org/#/q/I9082be077b59acd3a39910fa64e29147cb5c2dd7

--

Thanks,

Matt

-- Slawek Kaplonski Senior software engineer Red Hat