kubernetes
/
apiserver
mirror of https://github.com/kubernetes/apiserver.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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
This commit is contained in:
Patrick Ohly 2021-12-11 12:10:21 +01:00 committed by Kubernetes Publisher
parent 81299c6580
commit ec795ae204
6 changed files with 38 additions and 29 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
pkg/registry/generic/registry/storage_factory.go
View File

@ -50,7 +50,7 @@ func StorageWithCacher() generic.StorageDecorator {
return s, d, err return s, d, err
} }
if klog.V(5).Enabled() { 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{ cacherConfig := cacherstorage.Config{

6
pkg/server/httplog/httplog.go
View File

@ -95,10 +95,12 @@ func DefaultStacktracePred(status int) bool {
return (status < http.StatusOK || status >= http.StatusInternalServerError) && status != http.StatusSwitchingProtocols return (status < http.StatusOK || status >= http.StatusInternalServerError) && status != http.StatusSwitchingProtocols
} }
const withLoggingLevel = 3
// WithLogging wraps the handler with logging. // WithLogging wraps the handler with logging.
func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { func WithLogging(handler http.Handler, pred StacktracePred) http.Handler {
return withLogging(handler, pred, func() bool { 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. // Header implements http.ResponseWriter.

6
pkg/storage/etcd3/logger.go
View File

@ -33,19 +33,19 @@ const klogWrapperDepth = 4
func (klogWrapper) Info(args ...interface{}) { func (klogWrapper) Info(args ...interface{}) {
if klog.V(5).Enabled() { if klog.V(5).Enabled() {
klog.InfoDepth(klogWrapperDepth, args...) klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprint(args...))
} }
} }
func (klogWrapper) Infoln(args ...interface{}) { func (klogWrapper) Infoln(args ...interface{}) {
if klog.V(5).Enabled() { 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{}) { func (klogWrapper) Infof(format string, args ...interface{}) {
if klog.V(5).Enabled() { if klog.V(5).Enabled() {
klog.InfoDepth(klogWrapperDepth, fmt.Sprintf(format, args...)) klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprintf(format, args...))
} }
} }

5
pkg/util/flowcontrol/apf_controller.go
View File

@ -608,9 +608,10 @@ func (meal *cfgMeal) digestFlowSchemasLocked(newFSs []*flowcontrol.FlowSchema) {
} }
meal.cfgCtlr.flowSchemas = fsSeq meal.cfgCtlr.flowSchemas = fsSeq
if klog.V(5).Enabled() { klogV := klog.V(5)
if klogV.Enabled() {
for _, fs := range fsSeq { for _, fs := range fsSeq {
klog.Infof("Using FlowSchema %s", fcfmt.Fmt(fs)) klogV.Infof("Using FlowSchema %s", fcfmt.Fmt(fs))
} }
} }
} }

43
pkg/util/flowcontrol/fairqueuing/queueset/queueset.go
View File

@ -637,8 +637,9 @@ func (qs *queueSet) enqueueLocked(request *request) {
if queue.requests.Length() == 0 && queue.requestsExecuting == 0 { if queue.requests.Length() == 0 && queue.requestsExecuting == 0 {
// the queue’s start R is set to the virtual time. // the queue’s start R is set to the virtual time.
queue.nextDispatchR = qs.currentR queue.nextDispatchR = qs.currentR
if klog.V(6).Enabled() { klogV := klog.V(6)
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) 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) 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()) metrics.AddRequestConcurrencyInUse(qs.qCfg.Name, fsName, req.MaxSeats())
qs.reqsObsPair.RequestsExecuting.Add(1) qs.reqsObsPair.RequestsExecuting.Add(1)
qs.execSeatsObs.Add(float64(req.MaxSeats())) qs.execSeatsObs.Add(float64(req.MaxSeats()))
if klog.V(5).Enabled() { klogV := klog.V(5)
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) 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 return req
} }
@ -717,8 +719,9 @@ func (qs *queueSet) dispatchLocked() bool {
metrics.AddRequestConcurrencyInUse(qs.qCfg.Name, request.fsName, request.MaxSeats()) metrics.AddRequestConcurrencyInUse(qs.qCfg.Name, request.fsName, request.MaxSeats())
qs.reqsObsPair.RequestsExecuting.Add(1) qs.reqsObsPair.RequestsExecuting.Add(1)
qs.execSeatsObs.Add(float64(request.MaxSeats())) qs.execSeatsObs.Add(float64(request.MaxSeats()))
if klog.V(6).Enabled() { klogV := klog.V(6)
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", 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, 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) 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()) { if !qs.canAccommodateSeatsLocked(oldestReqFromMinQueue.MaxSeats()) {
// since we have not picked the queue with the minimum virtual finish // since we have not picked the queue with the minimum virtual finish
// time, we are not going to advance the round robin index here. // time, we are not going to advance the round robin index here.
if klog.V(4).Enabled() { klogV := klog.V(4)
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", 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) qs.qCfg.Name, oldestReqFromMinQueue.descr1, oldestReqFromMinQueue.descr2, oldestReqFromMinQueue.MaxSeats(), minQueue.index, qs.totRequestsExecuting, qs.totSeatsInUse, qs.dCfg.ConcurrencyLimit)
} }
return nil, nil return nil, nil
@ -876,28 +880,29 @@ func (qs *queueSet) finishRequestLocked(r *request) {
} }
defer func() { defer func() {
klogV := klog.V(6)
if r.workEstimate.AdditionalLatency <= 0 { if r.workEstimate.AdditionalLatency <= 0 {
// release the seats allocated to this request immediately // release the seats allocated to this request immediately
releaseSeatsLocked() releaseSeatsLocked()
if !klog.V(6).Enabled() { if !klogV.Enabled() {
} else if r.queue != nil { } 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, 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) r.queue.nextDispatchR, actualServiceDuration.Seconds(), r.queue.requests.Length(), r.queue.requests.QueueSum(), r.queue.requestsExecuting, r.queue.seatsInUse)
} else { } 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 return
} }
additionalLatency := r.workEstimate.AdditionalLatency additionalLatency := r.workEstimate.AdditionalLatency
if !klog.V(6).Enabled() { if !klogV.Enabled() {
} else if r.queue != nil { } 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, 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) r.queue.nextDispatchR, actualServiceDuration.Seconds(), r.queue.requests.Length(), r.queue.requests.QueueSum(), r.queue.requestsExecuting, r.queue.seatsInUse)
} else { } 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, // EventAfterDuration will execute the event func in a new goroutine,
// so the seats allocated to this request will be released after // 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() defer qs.lock.Unlock()
now := qs.clock.Now() now := qs.clock.Now()
releaseSeatsLocked() releaseSeatsLocked()
if !klog.V(6).Enabled() { if !klogV.Enabled() {
} else if r.queue != nil { } 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, 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) r.queue.requests.Length(), r.queue.requests.QueueSum(), r.queue.requestsExecuting, r.queue.seatsInUse)
} else { } 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() qs.dispatchAsMuchAsPossibleLocked()
}, additionalLatency) }, additionalLatency)
@ -945,8 +950,8 @@ func (qs *queueSet) boundNextDispatchLocked(queue *queue) {
} }
var virtualStartBound = oldestReqFromMinQueue.arrivalR var virtualStartBound = oldestReqFromMinQueue.arrivalR
if queue.nextDispatchR < virtualStartBound { if queue.nextDispatchR < virtualStartBound {
if klog.V(4).Enabled() { if klogV := klog.V(4); klogV.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)) 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 queue.nextDispatchR = virtualStartBound
} }

5
pkg/util/flowcontrol/fairqueuing/testing/eventclock/fake.go
View File

@ -44,7 +44,8 @@ type waitGroupCounter struct {
var _ counter.GoRoutineCounter = (*waitGroupCounter)(nil) var _ counter.GoRoutineCounter = (*waitGroupCounter)(nil)
func (wgc *waitGroupCounter) Add(delta int) { func (wgc *waitGroupCounter) Add(delta int) {
if klog.V(7).Enabled() { klogV := klog.V(7)
if klogV.Enabled() {
var pcs [10]uintptr var pcs [10]uintptr
nCallers := runtime.Callers(2, pcs[:]) nCallers := runtime.Callers(2, pcs[:])
frames := runtime.CallersFrames(pcs[:nCallers]) frames := runtime.CallersFrames(pcs[:nCallers])
@ -64,7 +65,7 @@ func (wgc *waitGroupCounter) Add(delta int) {
break 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) wgc.wg.Add(delta)
} }