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) }