From 8c802205232ac66b2e52137f8869c3aed73c54b1 Mon Sep 17 00:00:00 2001 From: RyuRyu <1029348431@qq.com> Date: Mon, 24 Jun 2024 23:24:47 +0800 Subject: [PATCH] grpclog: remove Debugf method to avoid unnecessary evaluation (#7330) --- internal/grpclog/prefixLogger.go | 18 ------------------ internal/xds/bootstrap/bootstrap.go | 4 +++- .../balancer/priority/balancer_priority.go | 12 +++++++++--- xds/internal/balancer/ringhash/ring.go | 12 +++++++++--- xds/internal/xdsclient/authority.go | 16 ++++++++++++---- xds/internal/xdsclient/transport/transport.go | 15 +++++++++------ 6 files changed, 42 insertions(+), 35 deletions(-) diff --git a/internal/grpclog/prefixLogger.go b/internal/grpclog/prefixLogger.go index faa998de7..0cbcb0d0c 100644 --- a/internal/grpclog/prefixLogger.go +++ b/internal/grpclog/prefixLogger.go @@ -61,24 +61,6 @@ func (pl *PrefixLogger) Errorf(format string, args ...any) { ErrorDepth(1, fmt.Sprintf(format, args...)) } -// Debugf does info logging at verbose level 2. -func (pl *PrefixLogger) Debugf(format string, args ...any) { - // TODO(6044): Refactor interfaces LoggerV2 and DepthLogger, and maybe - // rewrite PrefixLogger a little to ensure that we don't use the global - // `Logger` here, and instead use the `logger` field. - if !Logger.V(2) { - return - } - if pl != nil { - // Handle nil, so the tests can pass in a nil logger. - format = pl.prefix + format - pl.logger.InfoDepth(1, fmt.Sprintf(format, args...)) - return - } - InfoDepth(1, fmt.Sprintf(format, args...)) - -} - // V reports whether verbosity level l is at least the requested verbose level. func (pl *PrefixLogger) V(l int) bool { // TODO(6044): Refactor interfaces LoggerV2 and DepthLogger, and maybe diff --git a/internal/xds/bootstrap/bootstrap.go b/internal/xds/bootstrap/bootstrap.go index 2b789320c..7be267a81 100644 --- a/internal/xds/bootstrap/bootstrap.go +++ b/internal/xds/bootstrap/bootstrap.go @@ -509,7 +509,9 @@ func bootstrapConfigFromEnvVariable() ([]byte, error) { fContent := envconfig.XDSBootstrapFileContent if fName != "" { - logger.Debugf("Using bootstrap file with name %q", fName) + if logger.V(2) { + logger.Infof("Using bootstrap file with name %q", fName) + } return bootstrapFileReadFunc(fName) } diff --git a/xds/internal/balancer/priority/balancer_priority.go b/xds/internal/balancer/priority/balancer_priority.go index 4655bf418..0be807c13 100644 --- a/xds/internal/balancer/priority/balancer_priority.go +++ b/xds/internal/balancer/priority/balancer_priority.go @@ -83,7 +83,9 @@ var ( // Caller must hold b.mu. func (b *priorityBalancer) syncPriority(childUpdating string) { if b.inhibitPickerUpdates { - b.logger.Debugf("Skipping update from child policy %q", childUpdating) + if b.logger.V(2) { + b.logger.Infof("Skipping update from child policy %q", childUpdating) + } return } for p, name := range b.priorities { @@ -99,12 +101,16 @@ func (b *priorityBalancer) syncPriority(childUpdating string) { (child.state.ConnectivityState == connectivity.Connecting && child.initTimer != nil) || p == len(b.priorities)-1 { if b.childInUse != child.name || child.name == childUpdating { - b.logger.Debugf("childInUse, childUpdating: %q, %q", b.childInUse, child.name) + if b.logger.V(2) { + b.logger.Infof("childInUse, childUpdating: %q, %q", b.childInUse, child.name) + } // If we switch children or the child in use just updated its // picker, push the child's picker to the parent. b.cc.UpdateState(child.state) } - b.logger.Debugf("Switching to (%q, %v) in syncPriority", child.name, p) + if b.logger.V(2) { + b.logger.Infof("Switching to (%q, %v) in syncPriority", child.name, p) + } b.switchToChild(child, p) break } diff --git a/xds/internal/balancer/ringhash/ring.go b/xds/internal/balancer/ringhash/ring.go index eac89b5b4..45dbb2d2a 100644 --- a/xds/internal/balancer/ringhash/ring.go +++ b/xds/internal/balancer/ringhash/ring.go @@ -67,11 +67,15 @@ type ringEntry struct { // // Must be called with a non-empty subConns map. func newRing(subConns *resolver.AddressMap, minRingSize, maxRingSize uint64, logger *grpclog.PrefixLogger) *ring { - logger.Debugf("newRing: number of subConns is %d, minRingSize is %d, maxRingSize is %d", subConns.Len(), minRingSize, maxRingSize) + if logger.V(2) { + logger.Infof("newRing: number of subConns is %d, minRingSize is %d, maxRingSize is %d", subConns.Len(), minRingSize, maxRingSize) + } // https://github.com/envoyproxy/envoy/blob/765c970f06a4c962961a0e03a467e165b276d50f/source/common/upstream/ring_hash_lb.cc#L114 normalizedWeights, minWeight := normalizeWeights(subConns) - logger.Debugf("newRing: normalized subConn weights is %v", normalizedWeights) + if logger.V(2) { + logger.Infof("newRing: normalized subConn weights is %v", normalizedWeights) + } // Normalized weights for {3,3,4} is {0.3,0.3,0.4}. @@ -82,7 +86,9 @@ func newRing(subConns *resolver.AddressMap, minRingSize, maxRingSize uint64, log scale := math.Min(math.Ceil(minWeight*float64(minRingSize))/minWeight, float64(maxRingSize)) ringSize := math.Ceil(scale) items := make([]*ringEntry, 0, int(ringSize)) - logger.Debugf("newRing: creating new ring of size %v", ringSize) + if logger.V(2) { + logger.Infof("newRing: creating new ring of size %v", ringSize) + } // For each entry, scale*weight nodes are generated in the ring. // diff --git a/xds/internal/xdsclient/authority.go b/xds/internal/xdsclient/authority.go index b80cbf732..e6ffff2bb 100644 --- a/xds/internal/xdsclient/authority.go +++ b/xds/internal/xdsclient/authority.go @@ -229,7 +229,9 @@ func (a *authority) updateResourceStateAndScheduleCallbacks(rType xdsresource.Ty } } // Sync cache. - a.logger.Debugf("Resource type %q with name %q added to cache", rType.TypeName(), name) + if a.logger.V(2) { + a.logger.Infof("Resource type %q with name %q added to cache", rType.TypeName(), name) + } state.cache = uErr.resource // Set status to ACK, and clear error state. The metadata might be a // NACK metadata because some other resources in the same response @@ -454,7 +456,9 @@ func (a *authority) close() { } func (a *authority) watchResource(rType xdsresource.Type, resourceName string, watcher xdsresource.ResourceWatcher) func() { - a.logger.Debugf("New watch for type %q, resource name %q", rType.TypeName(), resourceName) + if a.logger.V(2) { + a.logger.Infof("New watch for type %q, resource name %q", rType.TypeName(), resourceName) + } a.resourcesMu.Lock() defer a.resourcesMu.Unlock() @@ -471,7 +475,9 @@ func (a *authority) watchResource(rType xdsresource.Type, resourceName string, w // instruct the transport layer to send a DiscoveryRequest for the same. state := resources[resourceName] if state == nil { - a.logger.Debugf("First watch for type %q, resource name %q", rType.TypeName(), resourceName) + if a.logger.V(2) { + a.logger.Infof("First watch for type %q, resource name %q", rType.TypeName(), resourceName) + } state = &resourceState{ watchers: make(map[xdsresource.ResourceWatcher]bool), md: xdsresource.UpdateMetadata{Status: xdsresource.ServiceStatusRequested}, @@ -510,7 +516,9 @@ func (a *authority) watchResource(rType xdsresource.Type, resourceName string, w // There are no more watchers for this resource, delete the state // associated with it, and instruct the transport to send a request // which does not include this resource name. - a.logger.Debugf("Removing last watch for type %q, resource name %q", rType.TypeName(), resourceName) + if a.logger.V(2) { + a.logger.Infof("Removing last watch for type %q, resource name %q", rType.TypeName(), resourceName) + } delete(resources, resourceName) a.sendDiscoveryRequestLocked(rType, resources) } diff --git a/xds/internal/xdsclient/transport/transport.go b/xds/internal/xdsclient/transport/transport.go index fb7860f98..e0636084b 100644 --- a/xds/internal/xdsclient/transport/transport.go +++ b/xds/internal/xdsclient/transport/transport.go @@ -48,8 +48,7 @@ import ( // Any per-RPC level logs which print complete request or response messages // should be gated at this verbosity level. Other per-RPC level logs which print -// terse output should be at `INFO` and verbosity 2, which corresponds to using -// the `Debugf` method on the logger. +// terse output should be at `INFO` and verbosity 2. const perRPCVerbosityLevel = 9 type adsStream = v3adsgrpc.AggregatedDiscoveryService_StreamAggregatedResourcesClient @@ -298,7 +297,9 @@ func (t *Transport) sendAggregatedDiscoveryServiceRequest(stream adsStream, send if t.logger.V(perRPCVerbosityLevel) { t.logger.Infof("ADS request sent: %v", pretty.ToJSON(req)) } else { - t.logger.Debugf("ADS request sent for type %q, resources: %v, version %q, nonce %q", resourceURL, resourceNames, version, nonce) + if t.logger.V(2) { + t.logger.Infof("ADS request sent for type %q, resources: %v, version %q, nonce %q", resourceURL, resourceNames, version, nonce) + } } t.onSendHandler(&ResourceSendInfo{URL: resourceURL, ResourceNames: resourceNames}) return nil @@ -311,8 +312,8 @@ func (t *Transport) recvAggregatedDiscoveryServiceResponse(stream adsStream) (re } if t.logger.V(perRPCVerbosityLevel) { t.logger.Infof("ADS response received: %v", pretty.ToJSON(resp)) - } else { - t.logger.Debugf("ADS response received for type %q, version %q, nonce %q", resp.GetTypeUrl(), resp.GetVersionInfo(), resp.GetNonce()) + } else if t.logger.V(2) { + t.logger.Infof("ADS response received for type %q, version %q, nonce %q", resp.GetTypeUrl(), resp.GetVersionInfo(), resp.GetNonce()) } return resp.GetResources(), resp.GetTypeUrl(), resp.GetVersionInfo(), resp.GetNonce(), nil } @@ -512,7 +513,9 @@ func (t *Transport) recv(stream adsStream) bool { stream: stream, version: rVersion, }) - t.logger.Debugf("Sending ACK for resource type: %q, version: %q, nonce: %q", url, rVersion, nonce) + if t.logger.V(2) { + t.logger.Infof("Sending ACK for resource type: %q, version: %q, nonce: %q", url, rVersion, nonce) + } } }