diff --git a/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go b/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go index 5262b74ccb..b2f31c5275 100644 --- a/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go +++ b/staging/src/k8s.io/apiserver/pkg/util/trace/trace.go @@ -19,6 +19,7 @@ package trace import ( "bytes" "fmt" + "math/rand" "time" "github.com/golang/glog" @@ -48,22 +49,38 @@ func (t *Trace) Step(msg string) { } func (t *Trace) Log() { - endTime := time.Now() - var buffer bytes.Buffer + // an explicit logging request should dump all the steps out at the higher level + t.logWithStepThreshold(0) +} - buffer.WriteString(fmt.Sprintf("Trace %q (started %v):\n", t.name, t.startTime)) +func (t *Trace) logWithStepThreshold(stepThreshold time.Duration) { + var buffer bytes.Buffer + tracenum := rand.Int31() + endTime := time.Now() + + totalTime := endTime.Sub(t.startTime) + buffer.WriteString(fmt.Sprintf("Trace[%d]: %q (started: %v) (total time: %v):\n", tracenum, t.name, t.startTime, totalTime)) 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) + if stepThreshold == 0 || stepDuration > stepThreshold || glog.V(4) { + buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] %v\n", tracenum, 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))) + stepDuration := endTime.Sub(lastStepTime) + if stepThreshold == 0 || stepDuration > stepThreshold || glog.V(4) { + buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] END\n", tracenum, endTime.Sub(t.startTime), stepDuration)) + } + glog.Info(buffer.String()) } func (t *Trace) LogIfLong(threshold time.Duration) { if time.Since(t.startTime) >= threshold { - t.Log() + // if any step took more than it's share of the total allowed time, it deserves a higher log level + stepThreshold := threshold / time.Duration(len(t.steps)+1) + t.logWithStepThreshold(stepThreshold) } }