Improve Logger Performance When Disabled

[rob05c]

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

[dfawley]

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

[dfawley]

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]

Sent #7467 to wrap in a verbosity check.

[dfawley]

@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.