Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Improve Logger Performance When Disabled #7463

Closed
rob05c opened this issue Jul 31, 2024 · 5 comments · Fixed by #7467 · May be fixed by #7471
Closed

Improve Logger Performance When Disabled #7463

rob05c opened this issue Jul 31, 2024 · 5 comments · Fixed by #7467 · May be fixed by #7471
Assignees
@zasweq
Labels
Type: Performance Performance improvements (CPU, network, memory, etc)

Comments

@rob05c
Copy link

rob05c commented Jul 31, 2024

Use case(s) - what problem will this feature solve?

We're seeing a large memory increase when enabling grpc-go/xds on a service, of a sustained ~100mb or about double the previous usage.

We tracked it down to this log line: https://github.com/grpc/grpc-go/blob/8bf2b3ee/balancer/leastrequest/leastrequest.go#L115

Which, for our environment, is creating a single 48kb line.

We don't have Info logging enabled. We have traces indicating the memory usage is from Printf, and is being called by the log library regardless if logging is enabled, here: https://github.com/grpc/grpc-go/blob/fbff2abb/grpclog/loggerv2.go#L194

Proposed Solution

I propose changing grpc-go/grpclog to not call Printf if the logger is io.Discard. I believe this can be done safely and without changing the interface, in manner similar to how the standard log package does it here.

For what it's worth, I've personally seen this problem in the past, and saw a large performance improvement at scale, both memory and CPU, doing a very similar fix in a similar log library in Apache Traffic Control here. Unlike C, Go Printf is quite expensive because it uses Reflection. Simple benchmarking shows Printf is about 20x slower than strconv.Atoi for an int, and can be enormous for structs.

If you agree, I'm happy to make a PR.

Alternatives Considered

We might also consider removing that log line. I don't have context for why it was added, or how useful it is. If the consensus is to remove it, I'm happy to make that PR as well. But I believe the issue will likely just recur elsewhere, and the deeper issue is incurring the Printf cost for disabled logs, and would very much like to fix it there.

Additional Context
@rob05c rob05c added the Type: Feature New features or improvements in behavior label Jul 31, 2024
@dfawley
Copy link
Member

dfawley commented Jul 31, 2024

This particular log should probably just be moved behind V(2). @zasweq can you take care of it?

@dfawley dfawley added Type: Performance Performance improvements (CPU, network, memory, etc) and removed Type: Feature New features or improvements in behavior labels Jul 31, 2024
@dfawley
Copy link
Member

dfawley commented Jul 31, 2024

I propose changing grpc-go/grpclog to not call Printf if the logger is io.Discard. I believe this can be done safely and without changing the interface, in manner similar to how the standard log package does it here.

I'm fine with this idea as well, but that won't solve all our problems, either. We have had other cases recently where the logged data needs to be computed from a function call that is expensive for whatever reason. We should be very careful about what we log by default (verbosity 0).

@zasweq zasweq mentioned this issue Aug 1, 2024
Merged
@zasweq
Copy link
Contributor

zasweq commented Aug 1, 2024

Sent #7467 to wrap in a verbosity check.

rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 1, 2024
@rob05c
Change logger to avoid Printf when disabled
d919665 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
@rob05c rob05c mentioned this issue Aug 1, 2024
Open
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 1, 2024
@rob05c
Change logger to avoid Printf when disabled
ffee86f 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
@dfawley
Copy link
Member

dfawley commented Aug 1, 2024

@rob05c If you are still at all interested in creating a PR to make grpclog identify and avoid calls when the logger is io.Discard, we would be happy to review & merge it, assuming it is mostly clean/straightforward to add in.

rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
5699771 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
e5368f3 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
62518be 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
463f9b1 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
ae6fd53 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
@rob05c
Copy link
Author

rob05c commented Aug 5, 2024

@dfawley Thanks! I am interested, PR is here: #7471

rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
bf693df 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 5, 2024
@rob05c
Change logger to avoid Printf when disabled
bd9603c 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 8, 2024
@rob05c
Change logger to avoid Printf when disabled
2da6dee 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 13, 2024
@rob05c
Change logger to avoid Printf when disabled
9ba1841 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 13, 2024
@rob05c
Change logger to avoid Printf when disabled
a9fc2ad 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 13, 2024
@rob05c
Change logger to avoid Printf when disabled
2afe640 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 13, 2024
@rob05c
Change logger to avoid Printf when disabled
2242738 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 13, 2024
@rob05c
Change logger to avoid Printf when disabled
1184eb7 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
55f27c9 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
db331db 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
2ceeacb 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
f640167 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
9d11b17 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
5fc37ea 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
5bdac9d 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 19, 2024
@rob05c
Change logger to avoid Printf when disabled
6cbab73 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 29, 2024
@rob05c
Change logger to avoid Printf when disabled
ff3d814 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Aug 29, 2024
@rob05c
Change logger to avoid Printf when disabled
aec0260 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Sep 15, 2024
@rob05c
Change logger to avoid Printf when disabled
d6c1c6e 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Sep 15, 2024
@rob05c
Change logger to avoid Printf when disabled
44cb3df 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Sep 15, 2024
@rob05c
Change logger to avoid Printf when disabled
0da4704 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Sep 15, 2024
@rob05c
Change logger to avoid Printf when disabled
7bb19d4 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
rob05c added a commit to rob05c/grpc-go that referenced this issue Sep 15, 2024
@rob05c
Change logger to avoid Printf when disabled
2bf7f34 
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@zasweq zasweq

Labels
Type: Performance Performance improvements (CPU, network, memory, etc)
Projects
None yet
Milestone
No milestone
3 participants
@rob05c @dfawley @zasweq