ActionSet handling perf tweaks #1650

ed-shilo · 2022-09-29T09:31:09Z

Change Overview

The proposed set of changes improves perf of Add ActionSet workflow handling in Kanister controller by fixing the following issues:

Currently controller's onAdd event handler starts an ActionSet execution goroutines after prevalidation stage, which contains several API calls to K8S apiserver. These calls take several seconds before spawning a goroutine, and considering the fact that go-client cache calls onAdd sequentially this adds significant time delay before starting ActionSets if multiple ones are submitted simultaneously.
If multiple ActionSets are handled in parallel, this makes a load on k8s api servers and makes it less responsive. It was measured that for 10 simultaneous ActionSet executions each k8s API call may take up to 1 sec during execution. To reduce server load it was decided to reduce number of k8s API calls where it's possible. For example, all calls to get ActionSet blueprint were replaced with a single call to Blueprint's List method with further lookup through received Blueprints.

As a proof of perf improvement I measured execution time of several ActionSets submitted simultaneously depending on their count and phase count in a corresponding blueprint. A test ActionSet just performed single KubeExec call to minimize phase execution impact.

Results:

Phases per Blueprint	Parallel ActionSets	Old execution time	New execution time
1	10	35 sec	24 sec
1	20	1 min 12 sec	1 min 1 sec
1	30	1 min 50 sec	1 min 16 sec
3	10	56 sec	42 sec
3	20	1 min 53 sec	1 min 22 sec
3	30	2 min 51 sec	2 min 4 sec
5	10	1 min 12 sec	1 min 2 sec
5	20	2 min 26 sec	2 min 4 sec
5	30	3 min 26 sec	3 min 0 sec

Pull request type

Please check the type of change your PR introduces:

Issues

fixes [BUG] Poor performance of ActionSet processing #1646

Test Plan

💪 Manual
⚡ Unit test
💚 E2E

github-actions · 2022-09-29T09:31:22Z

Thanks for submitting this pull request 🎉. The team will review it soon and get back to you.

If you haven't already, please take a moment to review our project contributing guideline and Code of Conduct document.

viveksinghggits

LGTM. I will let someone else have a look as well. thank you, good find 💯
cc @ihcsim

ed-shilo · 2022-10-03T07:25:20Z

@ihcsim Could you please take a look at these changes too?

pkg/param/param.go

pkg/controller/controller.go

denisvmedia

LGTM

pavannd1

Thank you @ed-shilo 💯

ihcsim

Thanks for working on this. I left some questions and comments. If needed, we can address them in a follow-up PR.

ihcsim · 2022-10-05T18:14:44Z

pkg/controller/controller.go

-		if err := c.onAddActionSet(v); err != nil {
-			log.Error().WithError(err).Print("Callback onAddActionSet() failed")
-		}
+		t, ctx := c.LoadOrStoreTomb(context.Background(), v.Name)


I know these are legacy code, but I am not sure what we gain by storing the tombs. Not like there is much savings from re-use, since the actionsets will have different names. FWIW, it also doesn't look like it's expensive to create a tomb anyway.

As I understand, originally the tomb was used for graceful action set deletion. In fact each submitted goroutine doesn't listen for tomb signals, but I suppose it's better to leave them wrapped with the tomb.

ihcsim · 2022-10-05T18:16:17Z

pkg/controller/controller.go

+}
+
+func (c *Controller) onAddActionSet(ctx context.Context, t *tomb.Tomb, as *crv1alpha1.ActionSet) error {
+	as, err := c.crClient.CrV1alpha1().ActionSets(as.GetNamespace()).Get(ctx, as.GetName(), v1.GetOptions{})


Any idea why this call is necessary, since we are already passing in as?

Seems like it's unnecessary, need to remove

ihcsim · 2022-10-05T18:18:42Z

pkg/controller/controller.go

+	bpMap := make(map[string]*crv1alpha1.Blueprint)
+	for _, bp := range bps.Items {
+		bpMap[bp.Name] = bp
+	}


What is the purpose of re-listing and storing all blueprints for a single actionset? An actionset is mapped to just one blueprint.

Also, how about just use the K8s client-go informers and its Lister() method to retrieve the needed blueprint and maintain the cache, instead of doing it ourselves?

I don't see where this is validated, but if I'm not mistaken according to the code actions in an actionset may have associations with different blueprints.
Using an informer will add need to wait after adding a blueprint and before adding an actions due to cache resync. Do we want such behavior?

not really @ed-shilo. An actionset can point to just one blueprint.

created blueprints not being available immediately might be a concern.

The blueprint informer watches for new blueprints and updates its indexer accordingly. Try add a new blueprint, the blueprint informer should respond immediately. I am not sure why we are using the low level cache directly here, but it looks like we are already using client-go caching mechanism.

Re-sync applies to existing resources, when client-go tries to reconcile any differences between the cache and the data in its store.

@ed-shilo You are right about the 1:n mapping between actionset and blueprint. It looks like an actionset can have multiple actions, each of which can point to whichever blueprint it wants, even though downstream normally associate one actionset to one blueprint. Not sure why the API is designed that way.

@ihcsim tried to use lister for getting blueprints, but as I see a newly created blueprint goes into cache after some small time. In tests this is observed in failing of attempts to add an action set linked with an already added blueprint due to cache miss. Are we OK with this?

You are right, even though we don't use different blueprints for separate actions in an actionset, it does look like the code allows it.

My guess is that caching isn't a major contributor to the bottleneck. If anything, I will be suspicious of code like this where every phase hits a recursive reflection call. It can get expensive if there are sophisticated Go template statements.

Is it formally assumed that it should have the same value in case of multiple actions?

No, we can't assume that anymore. If the API let user do multiple blueprints, we have to support it.

Re: missing cache, did you use the informers lister or the cache lister. Looks like our code is using the cache one.

@ihcsim I used the lister from the link you proposed previosly. As far as I see, it uses caching.

ihcsim · 2022-10-05T18:36:10Z

pkg/controller/controller.go

+			c.logAndErrorEvent(ctx, "Could not get blueprint:", "Blueprint not specified", err, as)
+			break
+		}
+		bp, ok := bps[a.Blueprint]


I recommend using the client-go informers to retrieve the blueprint from its cache, instead of managing the cache ourselves.

Same question about adding need to wait between bp and as creation.

ihcsim · 2022-10-05T20:38:19Z

pkg/controller/controller.go

 	if err != nil {
 		return errors.WithStack(err)
 	}
 	if err := validate.ActionSet(as); err != nil {
 		return err
 	}
+	bps, err := c.createBpCache(ctx, as.GetNamespace())


This will get expensive during a controller restart or if the actionset get re-queued. See #1267. IIRC, on restart, the controller will call onAddActionSet() on all existing actionset resources. With this change, the controller will create a map of all blueprints for every known actionset.

ed-shilo · 2022-10-10T10:06:53Z

@ihcsim @viveksinghggits @pavannd1 I've opened the follow-up PR #1668, which addresses the rest of comments left after merge. I decided to return back direct retrievals of blueprints from the API server, as it seems that using caches brings much more problems in comparison with its contribution to overall workflow runtime.

ed-shilo requested review from ihcsim, pavannd1 and viveksinghggits September 29, 2022 09:31

ed-shilo assigned ihcsim, ed-shilo and viveksinghggits Sep 29, 2022

infraq added this to In Progress in Kanister Sep 29, 2022

ed-shilo force-pushed the keu/ed-shilo/K10-12812-as-perf branch from 3123cad to 4d54af2 Compare September 30, 2022 15:03

viveksinghggits reviewed Sep 30, 2022

View reviewed changes

ed-shilo force-pushed the keu/ed-shilo/K10-12812-as-perf branch from 4d54af2 to 4dea2e0 Compare October 3, 2022 06:38

denisvmedia reviewed Oct 3, 2022

View reviewed changes

pkg/param/param.go Outdated Show resolved Hide resolved

pavannd1 reviewed Oct 4, 2022

View reviewed changes

pkg/controller/controller.go Outdated Show resolved Hide resolved

pkg/controller/controller.go Outdated Show resolved Hide resolved

ed-shilo added 6 commits October 4, 2022 13:38

ActionSet handling perf tweaks

5174cc5

Fixed test

9749f93

Fixed unit tests

6341379

Fixed unit tests

bd20e9a

Addressed review comments

fdfcd76

Addressed review comments

6773589

ed-shilo force-pushed the keu/ed-shilo/K10-12812-as-perf branch from 093a47c to 6773589 Compare October 4, 2022 09:38

denisvmedia reviewed Oct 4, 2022

View reviewed changes

pkg/controller/controller.go Outdated Show resolved Hide resolved

Addressed review comments

e18b928

denisvmedia reviewed Oct 4, 2022

View reviewed changes

pkg/controller/controller.go Outdated Show resolved Hide resolved

denisvmedia reviewed Oct 4, 2022

View reviewed changes

pkg/controller/controller.go Outdated Show resolved Hide resolved

Addressed review comments

4f97f8d

denisvmedia reviewed Oct 4, 2022

View reviewed changes

pkg/controller/controller.go Outdated Show resolved Hide resolved

Addressed review comments

73d0373

denisvmedia approved these changes Oct 4, 2022

View reviewed changes

Kanister automation moved this from In Progress to Reviewer approved Oct 4, 2022

pavannd1 approved these changes Oct 5, 2022

View reviewed changes

ed-shilo added the kueue label Oct 5, 2022

mergify bot merged commit c2a8e32 into master Oct 5, 2022

mergify bot deleted the keu/ed-shilo/K10-12812-as-perf branch October 5, 2022 07:37

Kanister automation moved this from Reviewer approved to Done Oct 5, 2022

ihcsim reviewed Oct 5, 2022

View reviewed changes

ed-shilo added a commit that referenced this pull request Oct 10, 2022

Addressed comments from #1650

bc9f257

ed-shilo mentioned this pull request Oct 10, 2022

Follow-up PR for #1650 #1668

Merged

10 tasks

ed-shilo added a commit that referenced this pull request Oct 10, 2022

Addressed comments from #1650

c9525f2

ed-shilo added a commit that referenced this pull request Oct 11, 2022

Addressed comments from #1650

d3140f7

mergify bot pushed a commit that referenced this pull request Oct 11, 2022

Addressed comments from #1650 (#1668)

1b6ab8f

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ActionSet handling perf tweaks #1650

ActionSet handling perf tweaks #1650

ed-shilo commented Sep 29, 2022 •

edited

Loading

github-actions bot commented Sep 29, 2022

viveksinghggits left a comment •

edited

Loading

ed-shilo commented Oct 3, 2022

denisvmedia left a comment

pavannd1 left a comment

ihcsim left a comment

ihcsim Oct 5, 2022

ed-shilo Oct 10, 2022

ihcsim Oct 5, 2022

ed-shilo Oct 6, 2022

ihcsim Oct 5, 2022 •

edited

Loading

ed-shilo Oct 6, 2022

viveksinghggits Oct 6, 2022

viveksinghggits Oct 6, 2022

ihcsim Oct 6, 2022

ed-shilo Oct 6, 2022 •

edited

Loading

viveksinghggits Oct 6, 2022

ihcsim Oct 6, 2022

ihcsim Oct 6, 2022 •

edited

Loading

ed-shilo Oct 10, 2022

ihcsim Oct 5, 2022

ed-shilo Oct 6, 2022 •

edited

Loading

ihcsim Oct 5, 2022

ed-shilo commented Oct 10, 2022 •

edited

Loading

ActionSet handling perf tweaks #1650

ActionSet handling perf tweaks #1650

Conversation

ed-shilo commented Sep 29, 2022 • edited Loading

Change Overview

Pull request type

Issues

Test Plan

github-actions bot commented Sep 29, 2022

viveksinghggits left a comment • edited Loading

Choose a reason for hiding this comment

ed-shilo commented Oct 3, 2022

denisvmedia left a comment

Choose a reason for hiding this comment

pavannd1 left a comment

Choose a reason for hiding this comment

ihcsim left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ihcsim Oct 5, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ed-shilo Oct 6, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ihcsim Oct 6, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ed-shilo Oct 6, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ed-shilo commented Oct 10, 2022 • edited Loading

ed-shilo commented Sep 29, 2022 •

edited

Loading

viveksinghggits left a comment •

edited

Loading

ihcsim Oct 5, 2022 •

edited

Loading

ed-shilo Oct 6, 2022 •

edited

Loading

ihcsim Oct 6, 2022 •

edited

Loading

ed-shilo Oct 6, 2022 •

edited

Loading

ed-shilo commented Oct 10, 2022 •

edited

Loading