[BUG] Poor performance of ActionSet processing

[ed-shilo]

Describe the bug
When I create multiple action sets simultaneously, they are processed with delays on Kanister side.

To Reproduce
Steps to reproduce the behavior:

1. Add debug messages into onAdd event handler in Kanister's pkg/controller/controller.go file.
2. Create multiple action sets simultaneously
3. Observe in Kanister log that onAdd debug messages appear with delays.

Expected behavior
I suppose that processing of multiple action sets should be faster. At the moment this looks like a performance bottleneck for applications using Kanister.

Environment
Kubernetes Version/Provider: 1.21
Storage Provider: GKE
Cluster Size (#nodes): 3

Additional context
As an experiment I modified pkg/controller/controller.go with the following log calls:

+func objToString(obj interface{}) string {
+       switch v := obj.(type) {
+       case *crv1alpha1.ActionSet:
+               return fmt.Sprintf("ActionSet{\"name\": \"%s\", \"uuid\": \"%s\"}", v.Name, v.UID)
+       case *crv1alpha1.Blueprint:
+               return fmt.Sprintf("Blueprint{\"name\": \"%s\", \"uuid\": \"%s\"}", v.Name, v.UID)
+       default:
+               return fmt.Sprintf("UnknownObject{\"type\": \"%T\"}", obj)
+       }
+}
+
 func (c *Controller) onAdd(obj interface{}) {
+       log.Info().Print("Controller::onAdd", field.M{"obj": objToString(obj)})
        o, ok := obj.(runtime.Object)
        if !ok {
                objType := fmt.Sprintf("%T", obj)
@@ -176,6 +188,7 @@ func (c *Controller) onUpdate(oldObj, newObj interface{}) {
 }
 
 func (c *Controller) onDelete(obj interface{}) {
+       log.Info().Print("Controller::onDelete", field.M{"obj": objToString(obj)})
        switch v := obj.(type) {
        case *crv1alpha1.ActionSet:
                if err := c.onDeleteActionSet(v); err != nil {

Then in a test application I created 10 action sets at once via golang k8s api, waited for their completion and deleted all of them. Observed the following in logs of a test application:

"Time: 20220922-16:07:35.351Z, Message Created ActionSet pvc-6-ngir57wj" <---- Such messages are logged right after calling ActionSet.Create()
"Time: 20220922-16:07:36.123Z, Message Created ActionSet pvc-1-ngil6thx" 
"Time: 20220922-16:07:39.113Z, Message Created ActionSet pvc-9-ngikbwr6"
"Time: 20220922-16:07:39.917Z, Message Created ActionSet pvc-3-ngixrv48"
"Time: 20220922-16:07:40.708Z, Message Created ActionSet pvc-5-ngipkztn"
"Time: 20220922-16:07:42.316Z, Message Created ActionSet pvc-8-ngizglzm"
"Time: 20220922-16:07:42.520Z, Message Created ActionSet pvc-10-ngt67pv"
"Time: 20220922-16:07:43.711Z, Message Created ActionSet pvc-2-ngifjqwn"
"Time: 20220922-16:07:44.509Z, Message Created ActionSet pvc-4-ngix545n"
"Time: 20220922-16:07:44.716Z, Message Created ActionSet pvc-7-ngiz5nrt"
"Time: 20220922-16:07:52.116Z, Message Deleted ActionSet pvc-6-ngir57wj" <---- Such messages are logged right after ActionSet.Delete()
"Time: 20220922-16:07:54.313Z, Message Deleted ActionSet pvc-1-ngil6thx"
"Time: 20220922-16:07:58.332Z, Message Deleted ActionSet pvc-9-ngikbwr6"
"Time: 20220922-16:08:00.142Z, Message Deleted ActionSet pvc-3-ngixrv48"
"Time: 20220922-16:08:10.946Z, Message Deleted ActionSet pvc-5-ngipkztn"
"Time: 20220922-16:08:21.973Z, Message Deleted ActionSet pvc-8-ngizglzm"
"Time: 20220922-16:08:32.215Z, Message Deleted ActionSet pvc-10-ngt67pv"
"Time: 20220922-16:08:52.594Z, Message Deleted ActionSet pvc-2-ngifjqwn"
"Time: 20220922-16:08:53.194Z, Message Deleted ActionSet pvc-4-ngix545n"
"Time: 20220922-16:08:53.782Z, Message Deleted ActionSet pvc-7-ngiz5nrt"

and on Kanister side:

"Time: 2022-09-22T16:07:35.3500057Z, Message Controller::onAdd pvc-6-ngir57wj"
"Time: 2022-09-22T16:07:36.12121531Z, Message Controller::onAdd pvc-1-ngil6thx"
"Time: 2022-09-22T16:07:39.110795426Z, Message Controller::onAdd pvc-9-ngikbwr6"
"Time: 2022-09-22T16:07:40.167924955Z, Message Controller::onAdd pvc-3-ngixrv48"
"Time: 2022-09-22T16:07:45.775161887Z, Message Controller::onAdd pvc-5-ngipkztn"
"Time: 2022-09-22T16:07:55.769729013Z, Message Controller::onAdd pvc-8-ngizglzm"
"Time: 2022-09-22T16:08:02.167332988Z, Message Controller::onAdd pvc-10-ngt67pv"
"Time: 2022-09-22T16:08:06.766619434Z, Message Controller::onAdd pvc-2-ngifjqwn"
"Time: 2022-09-22T16:08:13.173679056Z, Message Controller::onAdd pvc-4-ngix545n"
"Time: 2022-09-22T16:08:19.769290363Z, Message Controller::onAdd pvc-7-ngiz5nrt"
"Time: 2022-09-22T16:08:26.167965139Z, Message Controller::onDelete pvc-6-ngir57wj"
"Time: 2022-09-22T16:08:26.169936496Z, Message Controller::onDelete pvc-1-ngil6thx"
"Time: 2022-09-22T16:08:26.172442064Z, Message Controller::onDelete pvc-9-ngikbwr6"
"Time: 2022-09-22T16:08:26.177037769Z, Message Controller::onDelete pvc-3-ngixrv48"
"Time: 2022-09-22T16:08:26.187949371Z, Message Controller::onDelete pvc-5-ngipkztn"
"Time: 2022-09-22T16:08:26.195837893Z, Message Controller::onDelete pvc-8-ngizglzm"
"Time: 2022-09-22T16:08:32.210891539Z, Message Controller::onDelete pvc-10-ngt67pv"
"Time: 2022-09-22T16:08:52.594266832Z, Message Controller::onDelete pvc-2-ngifjqwn"
"Time: 2022-09-22T16:08:53.193679498Z, Message Controller::onDelete pvc-4-ngix545n"
"Time: 2022-09-22T16:08:53.779738608Z, Message Controller::onDelete pvc-7-ngiz5nrt"

Here we can see that there's 44 sec delay between moments of adding pvc-6-ngir57wj and pvc-7-ngiz5nrt.

[github-actions]

Thanks for opening this issue 👍. The team will review it shortly.

If this is a bug report, make sure to include clear instructions how on to reproduce the problem with minimal reproducible examples, where possible. If this is a security report, please review our security policy as outlined in SECURITY.md.

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