WIP: Revert call to protosanitizer.StripSecrets(req) back to logGRPC()

[mpatlasov]

And add unit-test for logGRPC(). Let's see the performance of protosanitizer.StripSecrets(req) after kubernetes-csi/csi-lib-utils#184.

[k8s-ci-robot]

Adding the "do-not-merge/release-note-label-needed" label because no release-note block was detected, please follow our release note process to remove it.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: mpatlasov
Once this PR has been reviewed and has the lgtm label, please assign sunnylovestiramisu for approval. For more information see the Code Review Process.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

• OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[mpatlasov]

Now, when logGRPC() call is iterated 100,000,000 times in the unit test:

# Before adding protosanitizer.StripSecrets(req) to logGRPC():
$ go test -c -o /tmp/test ./pkg/gce-pd-csi-driver
$ time /tmp/test -test.run=TestLogGRPC
...
real	0m59.511s

# After adding protosanitizer.StripSecrets(req) to logGRPC():
$ go test -c -o /tmp/test ./pkg/gce-pd-csi-driver
$ time /tmp/test -test.run=TestLogGRPC
...
real	1m7.355s

[msau42]

Thanks! The performance number looks good, are you also able to get memory usage?

[k8s-ci-robot]

@mpatlasov: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
pull-gcp-compute-persistent-disk-csi-driver-verify	51c1dd1	link	true	/test pull-gcp-compute-persistent-disk-csi-driver-verify
pull-gcp-compute-persistent-disk-csi-driver-unit	51c1dd1	link	true	/test pull-gcp-compute-persistent-disk-csi-driver-unit
pull-gcp-compute-persistent-disk-csi-driver-e2e	51c1dd1	link	true	/test pull-gcp-compute-persistent-disk-csi-driver-e2e
pull-gcp-compute-persistent-disk-csi-driver-e2e-windows-2022	51c1dd1	link	false	/test pull-gcp-compute-persistent-disk-csi-driver-e2e-windows-2022

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. I understand the commands that are listed here.

[mpatlasov]

Thanks! The performance number looks good, are you also able to get memory usage?

@msau42 , I used go test -memprofile <filename> -bench . to collect memory usage (in pkg/gce-pd-csi-driver dir, with all unit tests deleted except TestLogGRPC). Allocated space is 1.5GB bigger due to StripSecrets:

$ echo top | go tool pprof -alloc_space /tmp/mem-before-patch.prof 
File: gce-pd-csi-driver.test
Build ID: f6db89e5e090e2a67270505208537a1522b7e055
Type: alloc_space
Time: 2025-05-09 16:04:14 PDT
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) Showing nodes accounting for 16.95GB, 99.89% of 16.97GB total
Dropped 138 nodes (cum <= 0.08GB)
      flat  flat%   sum%        cum   cum%
   10.48GB 61.72% 61.72%    16.96GB 99.93%  sigs.k8s.io/gcp-compute-persistent-disk-csi-driver/pkg/gce-pd-csi-driver.logGRPC
    6.48GB 38.17% 99.89%     6.49GB 38.21%  fmt.Sprintf
         0     0% 99.89%    16.96GB 99.93%  sigs.k8s.io/gcp-compute-persistent-disk-csi-driver/pkg/gce-pd-csi-driver.TestLogGRPC
         0     0% 99.89%    16.96GB 99.93%  testing.tRunner
$ echo top | go tool pprof -alloc_space /tmp/mem-after-patch.prof 
File: gce-pd-csi-driver.test
Build ID: a3fe90295418e6c82c02037169cef40a6ee01055
Type: alloc_space
Time: 2025-05-09 16:06:20 PDT
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) Showing nodes accounting for 18.43GB, 99.91% of 18.44GB total
Dropped 77 nodes (cum <= 0.09GB)
      flat  flat%   sum%        cum   cum%
   10.55GB 57.21% 57.21%    18.43GB   100%  sigs.k8s.io/gcp-compute-persistent-disk-csi-driver/pkg/gce-pd-csi-driver.logGRPC
    6.37GB 34.56% 91.77%     6.38GB 34.61%  fmt.Sprintf
    1.50GB  8.14% 99.91%     1.50GB  8.14%  github.com/kubernetes-csi/csi-lib-utils/protosanitizer.StripSecrets (inline)
         0     0% 99.91%    18.43GB   100%  sigs.k8s.io/gcp-compute-persistent-disk-csi-driver/pkg/gce-pd-csi-driver.TestLogGRPC
         0     0% 99.91%    18.43GB   100%  testing.tRunner

However inuse space is roughly the same:

$ echo top | go tool pprof -inuse_space /tmp/mem-before-patch.prof 
File: gce-pd-csi-driver.test
Build ID: f6db89e5e090e2a67270505208537a1522b7e055
Type: inuse_space
Time: 2025-05-09 16:04:14 PDT
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) Showing nodes accounting for 6741.88kB, 76.70% of 8790.19kB total
Showing top 10 nodes out of 92
      flat  flat%   sum%        cum   cum%
    2052kB 23.34% 23.34%     2052kB 23.34%  runtime.allocm
  536.37kB  6.10% 29.45%   536.37kB  6.10%  github.com/container-storage-interface/spec/lib/go/csi.init
  532.26kB  6.06% 35.50%   532.26kB  6.06%  google.golang.org/protobuf/reflect/protoregistry.(*Files).RegisterFile.func2
  532.26kB  6.06% 41.56%   532.26kB  6.06%  google.golang.org/protobuf/reflect/protoregistry.(*Types).register
  521.05kB  5.93% 47.48%   521.05kB  5.93%  go.opencensus.io/stats/view.NewMeter
  516.01kB  5.87% 53.35%   516.01kB  5.87%  golang.org/x/net/trace.init
  514.63kB  5.85% 59.21%   514.63kB  5.85%  regexp/syntax.appendRange
  512.62kB  5.83% 65.04%   512.62kB  5.83%  encoding/json.typeFields
  512.44kB  5.83% 70.87%   512.44kB  5.83%  google.golang.org/protobuf/internal/filedesc.(*Message).unmarshalFull
  512.23kB  5.83% 76.70%   512.23kB  5.83%  google.golang.org/protobuf/internal/filedesc.newRawFile
$ echo top | go tool pprof -inuse_space /tmp/mem-after-patch.prof 
File: gce-pd-csi-driver.test
Build ID: a3fe90295418e6c82c02037169cef40a6ee01055
Type: inuse_space
Time: 2025-05-09 16:06:20 PDT
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) Showing nodes accounting for 5684.90kB, 100% of 5684.90kB total
Showing top 10 nodes out of 40
      flat  flat%   sum%        cum   cum%
    2565kB 45.12% 45.12%     2565kB 45.12%  runtime.allocm
  532.26kB  9.36% 54.48%   532.26kB  9.36%  github.com/gogo/protobuf/proto.RegisterType
  526.13kB  9.25% 63.74%   526.13kB  9.25%  github.com/google/gnostic-models/openapiv3.init
  525.43kB  9.24% 72.98%   525.43kB  9.24%  k8s.io/apimachinery/pkg/api/meta.init
  512.05kB  9.01% 81.99%   512.05kB  9.01%  runtime.acquireSudog
  512.02kB  9.01% 90.99%   512.02kB  9.01%  google.golang.org/protobuf/internal/impl.getterForNullableScalar
  512.02kB  9.01%   100%   512.02kB  9.01%  fmt.Sprintf
         0     0%   100%   512.02kB  9.01%  google.golang.org/protobuf/encoding/protowire.init
         0     0%   100%   512.02kB  9.01%  google.golang.org/protobuf/internal/errors.New (inline)
         0     0%   100%   512.02kB  9.01%  google.golang.org/protobuf/internal/errors.format

[k8s-ci-robot]

PR needs rebase.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.