optimize allocations in redactStartedInformationCmd

[isopov]

Summary

I suggest to optimize allocations in redactStartedInformationCmd function used in debug logging commands and command started events.

Background & Motivation

In one of our services 20% of allocations come from this function. We use only events for metrics. CPU consumption is not that large - only 1.5%, but I believe some part of GC CPU consumption that stands for more than 10% of total service CPU consumption also originates from these allocations.

Benchmark attached gives the following results without suggested changes:

cpu: Intel(R) Core(TM) i9-14900K BenchmarkRedactStartedInformationCmd BenchmarkRedactStartedInformationCmd/0 BenchmarkRedactStartedInformationCmd/0-32	40476044 70.50 ns/op 112 B/op 1 allocs/op BenchmarkRedactStartedInformationCmd/1 BenchmarkRedactStartedInformationCmd/1-32 4045360 296.6 ns/op 320 B/op 2 allocs/op BenchmarkRedactStartedInformationCmd/5 BenchmarkRedactStartedInformationCmd/5-32 3126498 428.6 ns/op 320 B/op 2 allocs/op BenchmarkRedactStartedInformationCmd/10 BenchmarkRedactStartedInformationCmd/10-32 3266930 471.1 ns/op 320 B/op 2 allocs/op BenchmarkRedactStartedInformationCmd/100 BenchmarkRedactStartedInformationCmd/100-32 222031 4748 ns/op 2656 B/op 5 allocs/op BenchmarkRedactStartedInformationCmd/1000 BenchmarkRedactStartedInformationCmd/1000-32 26457 62563 ns/op 45280 B/op 12 allocs/op 

And with this changes:

BenchmarkRedactStartedInformationCmd BenchmarkRedactStartedInformationCmd/0 BenchmarkRedactStartedInformationCmd/0-32	27693193 85.49 ns/op 112 B/op 1 allocs/op BenchmarkRedactStartedInformationCmd/1 BenchmarkRedactStartedInformationCmd/1-32	10653050 138.6 ns/op 112 B/op 1 allocs/op BenchmarkRedactStartedInformationCmd/5 BenchmarkRedactStartedInformationCmd/5-32 4048020 266.7 ns/op 144 B/op 1 allocs/op BenchmarkRedactStartedInformationCmd/10 BenchmarkRedactStartedInformationCmd/10-32 7370712 363.6 ns/op 192 B/op 1 allocs/op BenchmarkRedactStartedInformationCmd/100 BenchmarkRedactStartedInformationCmd/100-32 571992 1924 ns/op 1024 B/op 1 allocs/op BenchmarkRedactStartedInformationCmd/1000 BenchmarkRedactStartedInformationCmd/1000-32 62100 21280 ns/op 10240 B/op 1 allocs/op 

For some runs degradation of the case with 0 documentSequences is even bigger. I don't know how common is this case.

[isopov]

If this approach is OK, where should this utility function be placed?

[matthewdale]

The approach looks good. I don't see any other uses for this logic currently, so I think it's fine to keep it as an anonymous function here for now. If we end up using this logic more in the future, we can move it into a shared package.

[matthewdale]

Look good! 👍

Here are the before and after results on my workstation. I don't see the CPU time regression in the 0-size case and all other cases show good reduction in allocations, so it looks like a great optimization. Thanks!

❯ benchstat old.txt new.txt goos: darwin goarch: arm64 pkg: go.mongodb.org/mongo-driver/v2/x/mongo/driver cpu: Apple M1 Max │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ RedactStartedInformationCmd/0-10 26.38n ± 5% 26.43n ± 2% ~ (p=0.755 n=10) RedactStartedInformationCmd/1-10 74.46n ± 3% 43.62n ± 0% -41.42% (p=0.000 n=10) RedactStartedInformationCmd/5-10 124.6n ± 3% 119.6n ± 0% -4.05% (p=0.000 n=10) RedactStartedInformationCmd/10-10 191.1n ± 0% 188.4n ± 0% -1.41% (p=0.000 n=10) RedactStartedInformationCmd/100-10 1.562µ ± 1% 1.590µ ± 0% +1.83% (p=0.000 n=10) RedactStartedInformationCmd/1000-10 17.37µ ± 1% 16.14µ ± 1% -7.09% (p=0.000 n=10) geomean 329.0n 295.6n -10.18% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ RedactStartedInformationCmd/0-10 112.0 ± 0% 112.0 ± 0% ~ (p=1.000 n=10) ¹ RedactStartedInformationCmd/1-10 320.0 ± 0% 112.0 ± 0% -65.00% (p=0.000 n=10) RedactStartedInformationCmd/5-10 320.0 ± 0% 144.0 ± 0% -55.00% (p=0.000 n=10) RedactStartedInformationCmd/10-10 320.0 ± 0% 192.0 ± 0% -40.00% (p=0.000 n=10) RedactStartedInformationCmd/100-10 2.594Ki ± 0% 1.000Ki ± 0% -61.45% (p=0.000 n=10) RedactStartedInformationCmd/1000-10 44.22Ki ± 0% 10.00Ki ± 0% -77.39% (p=0.000 n=10) geomean 872.6 392.1 -55.06% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ RedactStartedInformationCmd/0-10 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ RedactStartedInformationCmd/1-10 2.000 ± 0% 1.000 ± 0% -50.00% (p=0.000 n=10) RedactStartedInformationCmd/5-10 2.000 ± 0% 1.000 ± 0% -50.00% (p=0.000 n=10) RedactStartedInformationCmd/10-10 2.000 ± 0% 1.000 ± 0% -50.00% (p=0.000 n=10) RedactStartedInformationCmd/100-10 5.000 ± 0% 1.000 ± 0% -80.00% (p=0.000 n=10) RedactStartedInformationCmd/1000-10 12.000 ± 0% 1.000 ± 0% -91.67% (p=0.000 n=10) geomean 2.798 1.000 -64.26% ¹ all samples are equal