From a27bd323a33425f5290d793d37860c43d12c9f31 Mon Sep 17 00:00:00 2001 From: deads2k Date: Tue, 27 Jun 2017 08:47:26 -0400 Subject: [PATCH] UPSTREAM: 47904: prioritize messages for long steps --- .../k8s.io/apiserver/pkg/util/trace/trace.go | 32 +++++++++++++++---- 1 file changed, 26 insertions(+), 6 deletions(-) diff --git a/vendor/k8s.io/kubernetes/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go b/vendor/k8s.io/kubernetes/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go index 5262b74ccb0b..2bbc9356f25c 100644 --- a/vendor/k8s.io/kubernetes/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go +++ b/vendor/k8s.io/kubernetes/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go @@ -48,22 +48,42 @@ func (t *Trace) Step(msg string) { } func (t *Trace) Log() { + // an explicit logging request should dump all the steps out at the higher level + t.logWithStepThreshold(0) +} + +// logWithStepThreshold will log exceptionally long steps at a higher log level than all the other "normal" steps. +// If the threshold is zero, then it just dumps at the higher level. +func (t *Trace) logWithStepThreshold(stepThreshold time.Duration) { endTime := time.Now() - var buffer bytes.Buffer + var allStepsBuffer bytes.Buffer + var importantStepsBuffer bytes.Buffer - buffer.WriteString(fmt.Sprintf("Trace %q (started %v):\n", t.name, t.startTime)) + allStepsBuffer.WriteString(fmt.Sprintf("Trace %q (started %v):\n", t.name, t.startTime)) lastStepTime := t.startTime for _, step := range t.steps { - buffer.WriteString(fmt.Sprintf("[%v] [%v] %v\n", step.stepTime.Sub(t.startTime), step.stepTime.Sub(lastStepTime), step.msg)) + stepDuration := step.stepTime.Sub(lastStepTime) + allStepsBuffer.WriteString(fmt.Sprintf("[%v] [%v] %v\n", step.stepTime.Sub(t.startTime), stepDuration, step.msg)) + if stepThreshold != 0 && stepDuration > stepThreshold { + importantStepsBuffer.WriteString(fmt.Sprintf("[%v] [%v] %v\n", step.stepTime.Sub(t.startTime), stepDuration, step.msg)) + } lastStepTime = step.stepTime } - buffer.WriteString(fmt.Sprintf("%q [%v] [%v] END\n", t.name, endTime.Sub(t.startTime), endTime.Sub(lastStepTime))) - glog.Info(buffer.String()) + allStepsBuffer.WriteString(fmt.Sprintf("%q [%v] [%v] END\n", t.name, endTime.Sub(t.startTime), endTime.Sub(lastStepTime))) + if stepThreshold == 0 { + glog.Info(allStepsBuffer.String()) + return + } + + glog.Info(importantStepsBuffer.String()) + glog.V(4).Info(allStepsBuffer.String()) } func (t *Trace) LogIfLong(threshold time.Duration) { if time.Since(t.startTime) >= threshold { - t.Log() + // if any step took more than 10% of the total time, it deserves a higher log level + stepThreshold := threshold / 10 + t.logWithStepThreshold(stepThreshold) } }