Scalability Testing: System NSM testing

[Bolodya1997]

Test plan

Use cases:

1. Client requests Local Endpoint.
2. Client requests Remote Endpoint.

Test scenarios:

1. Client requests Local Endpoint.
   • Setup
     1. Start NSM (Registry, NSMgr, Forwarder) on single node.
     2. Start E endpoints implementing N network services on the same node.
   • Test
     1. Start C clients each requesting R network services on the same node.
2. Client requests Remote Endpoint.
   • Setup
     1. Start NSM (Registry, NSMgr, Forwarder) on 2 nodes.
     2. Start E endpoints implementing N network services on the second node.
   • Test
     1. Start C clients each requesting R network services on the first node.

Tasks

1. Investigate how to run MD integration test with variable parameters to build graph dependencies for time, CPU, memory usage of NSM components during the test over those parameters. Estimation: 3d
2. Create MD integration test for (1) test scenario with E, N, C, R variable parameters and measure time, CPU, memory usage for all NSM components during the test. Estimation: 2d
3. Create MD integration test for (2) test scenario with E, N, C, R variable parameters and measure time, CPU, memory usage for all NSM components during the test. Estimation: 1d

Estimation

6d

[d-uzlov]

Here is my progress so far:

I have an automated test with the following scenario:

1. Deploy NSM
2. Deploy Prometheus
3. Set test params (numbers E, N, C from the issue description)
4. Generate configs for clients and endpoints
5. Deploy everything
6. Wait for all connections to successfully finish
7. Wait 30 seconds to make sure Prometheus scraped the pods
8. Delete everything
9. Wait 30 seconds more
10. Get data from Prometheus for test time window and generate plots

Plots' appearance is still WIP. Here are how plots from local case currently look like:

1 service, 1 client, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

1 service, 5 clients, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

1 service, 15 clients, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

1 service, 30 clients, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

Plots certainly need more work. Remote case is basically ready too (well, as much as local case is ready, with all the work left to with with the plots). We can also run comparisons with more different configurations, like "1 NS, 5 NSC vs 5 NS, 1 NSC", but I didn't have time to run them today.

[denis-tingaikin]

/cc @edwarnicke

[denis-tingaikin]

It seems to me it is a good first step. I think we also can measure Request latency and ping latency in Load. @edwarnicke, @d-uzlov What do you think?

[d-uzlov]

An update on current status:

I have improved plot time resolution. Here are few examples:

Local case, 1 service, 1 client, 1 endpoint

## NSM CPU usage  ## NSM memory usage 

Local case, 1 service, 15 clients, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

Local case, 5 services, 3 clients, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

Remote case, 1 service, 15 clients, 1 endpoint

## NSM CPU usage  ## NSM memory usage  ## Test CPU usage  ## Test memory usage 

[d-uzlov]

Also, here is a list of issues that I found while I was running scalability tests:

• https://github.com/networkservicemesh/deployments-k8s/issues/1999 (this one was already mentioned above)
• https://github.com/networkservicemesh/cmd-registry-k8s/issues/158
• https://github.com/networkservicemesh/deployments-k8s/issues/2003
• https://github.com/networkservicemesh/deployments-k8s/issues/2085

This issue is also related to scalability testing because it's basically impossible to read our current logs after scalability tests:

• https://github.com/networkservicemesh/sdk/issues/1008

[d-uzlov]

Another update:

1. There are now 2 separate cases, orthogonal to local/remote cases:
   • First delete clients and then endpoints. This way heal doesn't happen
   • First delete endpoints, and then clients. This way heal always starts for all connections.
2. I think I fixed all issues with the plot appearance.

Here are examples:

Local case, 1 service, 15 clients, 1 endpoint, without healing

## NSM CPU usage  ## Test CPU usage per pod  ## Average test CPU usage 

Local case, 1 service, 15 clients, 1 endpoint, with healing

## NSM CPU usage  ## Average test CPU usage 

[d-uzlov]

Another update:

• I have made few more improvements on plots.
• Also, here is an archive with full data from several test runs: results.zip

Few notes from these results:

1. I find it very interesting that "15 clients, 5 endpoints" case is much more CPU intensive in healing than "15 clients, 1 endpoint" case

 

2. in cases where I'm maxing out my PC, spire actually consumes very substantial amount of CPU


[d-uzlov]

I have few more improvements to test scenarios in mind:

1. Currently I check that a client successfully connected by monitoring ip interface list. Maybe it would be more accurate to check logs for request success message, because maybe there could be some delay between interface creation and request success.
2. Currently I create and delete all clients/endpoints at once. Alternatively we can create then in batches, and maybe do several iterations of create/delete/create. This would better cover healing.

[d-uzlov]

I made a check for request end, and it seems like requests actually end right after the interface is created. I think it still worth keeping, to check that we don't add elements that delay the request on its way back.

[d-uzlov]

I have added "clients restart" and "endpoints restart" cases. See linked pull request for details.

[d-uzlov]

Examples of plots after scalability heal test:

     

[edwarnicke]

@d-uzlov Why is it taking 15 second to establish or heal a connection? Where are we leaking all that time? I would expect 100s of milliseconds... not 15 seconds...

[d-uzlov]

Why is it taking us 15s to get a local connection going? That feels very long in terms of latency given that the latency through the cmd-forwarder-vpp is order of 100s of ms… where are we leaking all that time?

I checked it, and I think that the actual reason is that NSEs take some time to start. It takes ~4 seconds for an nse to get its SVID. If we have some load on the system, this time can probably be higher. Registration of an nse happens almost instantly, but maybe in some runs of the test there could also be some delay. In the current version of the test I basically wait for the creation of nse container and deploy clients, which affects load, and can increase time an nse takes to obtain an SVID, and maybe it can increase the delay for nse register registration. (edited)

I ran the test with sleep after endpoints deployment, and with this change a request takes ~0.5 second.

It may be because of synchronization between spire server and spire agents. It can be mitigated, but it's unclear if we should do it during our tests.

[d-uzlov]

@d-uzlov Why is it taking 15 second to establish or heal a connection? Where are we leaking all that time? I would expect 100s of milliseconds... not 15 seconds...

I modified the tests to include more info about how much time each step takes.

Here are results for a few runs

## 1 service, 1 client, 1 endpoint   ## 3 services, 5 clients, 1 endpoint  

Here we can see, that healing actually takes 1-2 seconds to connect to a new running endpoint, when there is no load. Realistically it can be in order of 100s of milliseconds, because precision of my measurements is ±1 second. However, when the system is under load, we have some issues. In the case 5 clients, 3 requests per client healing took ~10 seconds after the endpoint started. Even worse: I actually have troubles running tests with more clients/requests. 10 clients, 3 requests per client case just never succeeds. Granted, I run the tests in kind using WSL, so my results may not be representative of performance on a real system, but it still looks very strange. Even increasing timeout for healing to 5 minutes doesn't help: seems like some of the connections just never heal.

I guess it would be interesting to deploy new endpoints before deleting old endpoints. It would probably be closer to real-life cases of healing.

[d-uzlov]

I don't think that anything in particular in healing takes a lot of time. It's probably just the system as a whole becomes slow, so healing takes much more time than it should.

[edwarnicke]

@d-uzlov What system are you running on? Have you tried running this on packet?

[edwarnicke]

@d-uzlov The thing is... this whole thing looks very very very much like we have some poorly thoughout global Mutex in the NSMgr somewhere...

[edwarnicke]

@d-uzlov Do you have a sense of how much time we are spending in each component during heal?

[d-uzlov]

My CPU is Ryzen 1700@3.6. I run tests in a WSL2 instance which have 16 GB if RAM. RAM is never maxed out, but CPU is maxed out in heavy tests. Though, I have a feeling that half of the CPU load could be going into VM stuff and kind management.

Do you have a sense of how much time we are spending in each component during heal?

Not yet. We can try taking CPU profile shots but they will likely be messy. Maybe it would help to run tests with modified logs. I haven't touched them recently but I think they should provide enough per-connection info to tell which components take most time.

I believe Vlad is already using modified logs for NSM high load task, maybe he can already provide more info on what's happening in the nsmgr when we have a lot of connections.

[edwarnicke]

@d-uzlov I'd suggest you try on packet first and soonest... I'm betting the issue we are chasing is an artifact of your local env (laptops are good, but running a whole cluster in one for perf/scaling is asking a lot).

[edwarnicke]

@d-uzlov All of that said... you are doing a great job on the graphs and chasing stuff down :)

[d-uzlov]

Ok, I'll try running the tests on Packet. I have just read that Vlad found that packet is working fine under load, so maybe it's really just a local env or kind issue.

[d-uzlov]

I tried running the tests on packet, and it seems to also have issues with healing.

Here's how typical run of scalability heal test looks like

## Run 1  ## Run 2 (failed, heal never succeeded) 

As you can see, when heal succeeds, it can take long time. And often it just never succeeds, and the CPU load is very high. Actually, CPU load when heal starts is usually near number of connections * 1 core. Initial requests also take substantial amount of time.

I tried to gather logs and CPU profiles, but I got few issues integrating their gathering into nsm components and the tests, and I spent some time solving them, so I don't have them yet.

[d-uzlov]

Here are full logs and profiles from 2 failed runs with high load. This runs have identical setup but a bit different results. All profiles describe the period of 60 seconds, starting right after mark Delete endpoints-0....

Run 1

[run_1-netsvc=3-nse=1-nsc=10-remote.zip](https://github.com/networkservicemesh/deployments-k8s/files/6868607/run_1-netsvc.3-nse.1-nsc.10-remote.zip) 

Run 2

[run_2-netsvc=3-nse=1-nsc=10-remote.zip](https://github.com/networkservicemesh/deployments-k8s/files/6868610/run_2-netsvc.3-nse.1-nsc.10-remote.zip) 

As you can see, the second run has CPU usage spikes after the end of the test. This happens randomly, some runs have this, some don't. Another interesting thing to notice is that on the first run when healing starts there is only 1 spike from the nsmgr. On the second run there are:

1. One gigantic spike on forwarder
2. Two middle-sized spikes on one nsmgr and on another forwarder
3. One small spike on another nsmgr.

This also happens randomly, and it probably has the same cause as spikes after the end of the test, but I didn't really keep statistics of it, so I may be wrong here.

I tried to analyze the logs and profiles, but I didn't manage to find anything interesting quickly, and decided to gather more data. I didn't have time to read the logs that are linked to this message. I'll research it later.

[d-uzlov]

I found out that my modified logs actually broke healing, and that's the reason why it didn't work for me. However, CPU spikes and long delay for requests are not related to this issue.

Here are an example plot and full logs of a scalability heal test run after I fixed my issue:

[run_4-netsvc=3-nse=1-nsc=10-remote.zip](https://github.com/networkservicemesh/deployments-k8s/files/6877724/run_4-netsvc.3-nse.1-nsc.10-remote.zip) 

[d-uzlov]

Here is an example plot from scalability heal test with my local fixes for both CPU spikes and request delay


In this image we can actually still see relatively long delay before initial requests finish and before heal finishes. This delay is actually entirely different issue: scalability tests parse results of kubectl exec call, one for each of the pods in the test, and exec calls actually have substantial delay, ~2s for one call, with total delay being ~20s for this test with 10 clients. I'm not yet sure what we can do about this delay.

[d-uzlov]

The issue with kubectl exec delay is more or less fixed:

Run on local kind


Run on packet before fix


Run on packet after fix


We still have some delay, but it is constant, we no longer spend clients count * delay to check everything. I think we can tolerate 1-2s of constant delay for measuring.