From ec795ae20496237d57b885db7ddf0cdb539e0c57 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Sat, 11 Dec 2021 12:10:21 +0100 Subject: [PATCH] avoid klog Info calls without verbosity In the following code pattern, the log message will get logged with v=0 in JSON output although conceptually it has a higher verbosity: if klog.V(5).Enabled() { klog.Info("hello world") } Having the actual verbosity in the JSON output is relevant, for example for filtering out only the important info messages. The solution is to use klog.V(5).Info or something similar. Whether the outer if is necessary at all depends on how complex the parameters are. The return value of klog.V can be captured in a variable and be used multiple times to avoid the overhead for that function call and to avoid repeating the verbosity level. Kubernetes-commit: 9eaa2dc554e0c3d4485d4c916dfdbc2f517db2e0 --- .../generic/registry/storage_factory.go | 2 +- pkg/server/httplog/httplog.go | 6 ++- pkg/storage/etcd3/logger.go | 6 +-- pkg/util/flowcontrol/apf_controller.go | 5 ++- .../fairqueuing/queueset/queueset.go | 43 +++++++++++-------- .../fairqueuing/testing/eventclock/fake.go | 5 ++- 6 files changed, 38 insertions(+), 29 deletions(-) diff --git a/pkg/registry/generic/registry/storage_factory.go b/pkg/registry/generic/registry/storage_factory.go index 6a4426ee6..0e1d62f1b 100644 --- a/pkg/registry/generic/registry/storage_factory.go +++ b/pkg/registry/generic/registry/storage_factory.go @@ -50,7 +50,7 @@ func StorageWithCacher() generic.StorageDecorator { return s, d, err } if klog.V(5).Enabled() { - klog.InfoS("Storage caching is enabled", objectTypeToArgs(newFunc())...) + klog.V(5).InfoS("Storage caching is enabled", objectTypeToArgs(newFunc())...) } cacherConfig := cacherstorage.Config{ diff --git a/pkg/server/httplog/httplog.go b/pkg/server/httplog/httplog.go index 0e9ba1999..5a290fb63 100644 --- a/pkg/server/httplog/httplog.go +++ b/pkg/server/httplog/httplog.go @@ -95,10 +95,12 @@ func DefaultStacktracePred(status int) bool { return (status < http.StatusOK || status >= http.StatusInternalServerError) && status != http.StatusSwitchingProtocols } +const withLoggingLevel = 3 + // WithLogging wraps the handler with logging. func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { return withLogging(handler, pred, func() bool { - return klog.V(3).Enabled() + return klog.V(withLoggingLevel).Enabled() }) } @@ -280,7 +282,7 @@ func (rl *respLogger) Log() { } } - klog.InfoSDepth(1, "HTTP", keysAndValues...) + klog.V(withLoggingLevel).InfoSDepth(1, "HTTP", keysAndValues...) } // Header implements http.ResponseWriter. diff --git a/pkg/storage/etcd3/logger.go b/pkg/storage/etcd3/logger.go index 26be6ead9..651b51800 100644 --- a/pkg/storage/etcd3/logger.go +++ b/pkg/storage/etcd3/logger.go @@ -33,19 +33,19 @@ const klogWrapperDepth = 4 func (klogWrapper) Info(args ...interface{}) { if klog.V(5).Enabled() { - klog.InfoDepth(klogWrapperDepth, args...) + klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprint(args...)) } } func (klogWrapper) Infoln(args ...interface{}) { if klog.V(5).Enabled() { - klog.InfoDepth(klogWrapperDepth, fmt.Sprintln(args...)) + klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprintln(args...)) } } func (klogWrapper) Infof(format string, args ...interface{}) { if klog.V(5).Enabled() { - klog.InfoDepth(klogWrapperDepth, fmt.Sprintf(format, args...)) + klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprintf(format, args...)) } } diff --git a/pkg/util/flowcontrol/apf_controller.go b/pkg/util/flowcontrol/apf_controller.go index cf3aeba0c..78785d9a2 100644 --- a/pkg/util/flowcontrol/apf_controller.go +++ b/pkg/util/flowcontrol/apf_controller.go @@ -608,9 +608,10 @@ func (meal *cfgMeal) digestFlowSchemasLocked(newFSs []*flowcontrol.FlowSchema) { } meal.cfgCtlr.flowSchemas = fsSeq - if klog.V(5).Enabled() { + klogV := klog.V(5) + if klogV.Enabled() { for _, fs := range fsSeq { - klog.Infof("Using FlowSchema %s", fcfmt.Fmt(fs)) + klogV.Infof("Using FlowSchema %s", fcfmt.Fmt(fs)) } } } diff --git a/pkg/util/flowcontrol/fairqueuing/queueset/queueset.go b/pkg/util/flowcontrol/fairqueuing/queueset/queueset.go index 440975faf..92b8f74a8 100644 --- a/pkg/util/flowcontrol/fairqueuing/queueset/queueset.go +++ b/pkg/util/flowcontrol/fairqueuing/queueset/queueset.go @@ -637,8 +637,9 @@ func (qs *queueSet) enqueueLocked(request *request) { if queue.requests.Length() == 0 && queue.requestsExecuting == 0 { // the queue’s start R is set to the virtual time. queue.nextDispatchR = qs.currentR - if klog.V(6).Enabled() { - klog.Infof("QS(%s) at t=%s R=%v: initialized queue %d start R due to request %#+v %#+v", qs.qCfg.Name, now.Format(nsTimeFmt), queue.nextDispatchR, queue.index, request.descr1, request.descr2) + klogV := klog.V(6) + if klogV.Enabled() { + klogV.Infof("QS(%s) at t=%s R=%v: initialized queue %d start R due to request %#+v %#+v", qs.qCfg.Name, now.Format(nsTimeFmt), queue.nextDispatchR, queue.index, request.descr1, request.descr2) } } request.removeFromQueueLocked = queue.requests.Enqueue(request) @@ -676,8 +677,9 @@ func (qs *queueSet) dispatchSansQueueLocked(ctx context.Context, workEstimate *f metrics.AddRequestConcurrencyInUse(qs.qCfg.Name, fsName, req.MaxSeats()) qs.reqsObsPair.RequestsExecuting.Add(1) qs.execSeatsObs.Add(float64(req.MaxSeats())) - if klog.V(5).Enabled() { - klog.Infof("QS(%s) at t=%s R=%v: immediate dispatch of request %q %#+v %#+v, qs will have %d executing", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, fsName, descr1, descr2, qs.totRequestsExecuting) + klogV := klog.V(5) + if klogV.Enabled() { + klogV.Infof("QS(%s) at t=%s R=%v: immediate dispatch of request %q %#+v %#+v, qs will have %d executing", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, fsName, descr1, descr2, qs.totRequestsExecuting) } return req } @@ -717,8 +719,9 @@ func (qs *queueSet) dispatchLocked() bool { metrics.AddRequestConcurrencyInUse(qs.qCfg.Name, request.fsName, request.MaxSeats()) qs.reqsObsPair.RequestsExecuting.Add(1) qs.execSeatsObs.Add(float64(request.MaxSeats())) - if klog.V(6).Enabled() { - klog.Infof("QS(%s) at t=%s R=%v: dispatching request %#+v %#+v work %v from queue %d with start R %v, queue will have %d waiting & %d requests occupying %d seats, set will have %d seats occupied", + klogV := klog.V(6) + if klogV.Enabled() { + klogV.Infof("QS(%s) at t=%s R=%v: dispatching request %#+v %#+v work %v from queue %d with start R %v, queue will have %d waiting & %d requests occupying %d seats, set will have %d seats occupied", qs.qCfg.Name, request.startTime.Format(nsTimeFmt), qs.currentR, request.descr1, request.descr2, request.workEstimate, queue.index, queue.nextDispatchR, queue.requests.Length(), queue.requestsExecuting, queue.seatsInUse, qs.totSeatsInUse) } @@ -792,8 +795,9 @@ func (qs *queueSet) findDispatchQueueLocked() (*queue, *request) { if !qs.canAccommodateSeatsLocked(oldestReqFromMinQueue.MaxSeats()) { // since we have not picked the queue with the minimum virtual finish // time, we are not going to advance the round robin index here. - if klog.V(4).Enabled() { - klog.Infof("QS(%s): request %v %v seats %d cannot be dispatched from queue %d, waiting for currently executing requests to complete, %d requests are occupying %d seats and the limit is %d", + klogV := klog.V(4) + if klogV.Enabled() { + klogV.Infof("QS(%s): request %v %v seats %d cannot be dispatched from queue %d, waiting for currently executing requests to complete, %d requests are occupying %d seats and the limit is %d", qs.qCfg.Name, oldestReqFromMinQueue.descr1, oldestReqFromMinQueue.descr2, oldestReqFromMinQueue.MaxSeats(), minQueue.index, qs.totRequestsExecuting, qs.totSeatsInUse, qs.dCfg.ConcurrencyLimit) } return nil, nil @@ -876,28 +880,29 @@ func (qs *queueSet) finishRequestLocked(r *request) { } defer func() { + klogV := klog.V(6) if r.workEstimate.AdditionalLatency <= 0 { // release the seats allocated to this request immediately releaseSeatsLocked() - if !klog.V(6).Enabled() { + if !klogV.Enabled() { } else if r.queue != nil { - klog.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished all use of %d seats, adjusted queue %d start R to %v due to service time %.9fs, queue will have %d requests with %#v waiting & %d requests occupying %d seats", + klogV.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished all use of %d seats, adjusted queue %d start R to %v due to service time %.9fs, queue will have %d requests with %#v waiting & %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.MaxSeats(), r.queue.index, r.queue.nextDispatchR, actualServiceDuration.Seconds(), r.queue.requests.Length(), r.queue.requests.QueueSum(), r.queue.requestsExecuting, r.queue.seatsInUse) } else { - klog.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished all use of %d seats, qs will have %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.InitialSeats, qs.totRequestsExecuting, qs.totSeatsInUse) + klogV.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished all use of %d seats, qs will have %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.InitialSeats, qs.totRequestsExecuting, qs.totSeatsInUse) } return } additionalLatency := r.workEstimate.AdditionalLatency - if !klog.V(6).Enabled() { + if !klogV.Enabled() { } else if r.queue != nil { - klog.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished main use of %d seats but lingering on %d seats for %v seconds, adjusted queue %d start R to %v due to service time %.9fs, queue will have %d requests with %#v waiting & %d requests occupying %d seats", + klogV.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished main use of %d seats but lingering on %d seats for %v seconds, adjusted queue %d start R to %v due to service time %.9fs, queue will have %d requests with %#v waiting & %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.InitialSeats, r.workEstimate.FinalSeats, additionalLatency.Seconds(), r.queue.index, r.queue.nextDispatchR, actualServiceDuration.Seconds(), r.queue.requests.Length(), r.queue.requests.QueueSum(), r.queue.requestsExecuting, r.queue.seatsInUse) } else { - klog.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished main use of %d seats but lingering on %d seats for %v seconds, qs will have %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.InitialSeats, r.workEstimate.FinalSeats, additionalLatency.Seconds(), qs.totRequestsExecuting, qs.totSeatsInUse) + klogV.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished main use of %d seats but lingering on %d seats for %v seconds, qs will have %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.InitialSeats, r.workEstimate.FinalSeats, additionalLatency.Seconds(), qs.totRequestsExecuting, qs.totSeatsInUse) } // EventAfterDuration will execute the event func in a new goroutine, // so the seats allocated to this request will be released after @@ -908,13 +913,13 @@ func (qs *queueSet) finishRequestLocked(r *request) { defer qs.lock.Unlock() now := qs.clock.Now() releaseSeatsLocked() - if !klog.V(6).Enabled() { + if !klogV.Enabled() { } else if r.queue != nil { - klog.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished lingering on %d seats, queue %d will have %d requests with %#v waiting & %d requests occupying %d seats", + klogV.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished lingering on %d seats, queue %d will have %d requests with %#v waiting & %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.FinalSeats, r.queue.index, r.queue.requests.Length(), r.queue.requests.QueueSum(), r.queue.requestsExecuting, r.queue.seatsInUse) } else { - klog.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished lingering on %d seats, qs will have %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.FinalSeats, qs.totRequestsExecuting, qs.totSeatsInUse) + klogV.Infof("QS(%s) at t=%s R=%v: request %#+v %#+v finished lingering on %d seats, qs will have %d requests occupying %d seats", qs.qCfg.Name, now.Format(nsTimeFmt), qs.currentR, r.descr1, r.descr2, r.workEstimate.FinalSeats, qs.totRequestsExecuting, qs.totSeatsInUse) } qs.dispatchAsMuchAsPossibleLocked() }, additionalLatency) @@ -945,8 +950,8 @@ func (qs *queueSet) boundNextDispatchLocked(queue *queue) { } var virtualStartBound = oldestReqFromMinQueue.arrivalR if queue.nextDispatchR < virtualStartBound { - if klog.V(4).Enabled() { - klog.InfoS("AntiWindup tweaked queue", "QS", qs.qCfg.Name, "queue", queue.index, "time", qs.clock.Now().Format(nsTimeFmt), "requestDescr1", oldestReqFromMinQueue.descr1, "requestDescr2", oldestReqFromMinQueue.descr2, "newVirtualStart", virtualStartBound, "deltaVirtualStart", (virtualStartBound - queue.nextDispatchR)) + if klogV := klog.V(4); klogV.Enabled() { + klogV.InfoS("AntiWindup tweaked queue", "QS", qs.qCfg.Name, "queue", queue.index, "time", qs.clock.Now().Format(nsTimeFmt), "requestDescr1", oldestReqFromMinQueue.descr1, "requestDescr2", oldestReqFromMinQueue.descr2, "newVirtualStart", virtualStartBound, "deltaVirtualStart", (virtualStartBound - queue.nextDispatchR)) } queue.nextDispatchR = virtualStartBound } diff --git a/pkg/util/flowcontrol/fairqueuing/testing/eventclock/fake.go b/pkg/util/flowcontrol/fairqueuing/testing/eventclock/fake.go index 6f6ce3e6f..018fa8261 100644 --- a/pkg/util/flowcontrol/fairqueuing/testing/eventclock/fake.go +++ b/pkg/util/flowcontrol/fairqueuing/testing/eventclock/fake.go @@ -44,7 +44,8 @@ type waitGroupCounter struct { var _ counter.GoRoutineCounter = (*waitGroupCounter)(nil) func (wgc *waitGroupCounter) Add(delta int) { - if klog.V(7).Enabled() { + klogV := klog.V(7) + if klogV.Enabled() { var pcs [10]uintptr nCallers := runtime.Callers(2, pcs[:]) frames := runtime.CallersFrames(pcs[:nCallers]) @@ -64,7 +65,7 @@ func (wgc *waitGroupCounter) Add(delta int) { break } } - klog.InfoS("Add", "counter", fmt.Sprintf("%p", wgc), "delta", delta, "callers", callers) + klogV.InfoS("Add", "counter", fmt.Sprintf("%p", wgc), "delta", delta, "callers", callers) } wgc.wg.Add(delta) }