Skip to content

optimize allocations in redactStartedInformationCmd #2129

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged

Conversation

isopov
Copy link
Contributor

@isopov isopov commented Jul 15, 2025

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 isopov requested a review from a team as a code owner July 15, 2025 15:06
@isopov isopov requested a review from matthewdale July 15, 2025 15:06
@@ -158,13 +158,43 @@ type ResponseInfo struct {
}

func redactStartedInformationCmd(info startedInformation) bson.Raw {
intLen := func(n int) int {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

@matthewdale matthewdale left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@matthewdale matthewdale merged commit 910eb26 into mongodb:master Aug 6, 2025
31 of 34 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants