prioritize messages for long steps

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()
+	// an explicit logging request should dump all the steps out at the higher level
-	var buffer bytes.Buffer
+	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)
 	}
 }