github/kubernetes
1
0
Fork 0
mirror of https://github.com/k3s-io/kubernetes.git synced 2025-07-24 12:15:52 +00:00
Code Issues Projects Releases Wiki Activity

Merge pull request #47904 from deads2k/log-01-supress

Browse Source 
Automatic merge from submit-queue (batch tested with PRs 47484, 47904, 48034)

prioritize messages for long steps

This pull prioritizes the trace messages, so steps that are unusually large come out at the info level and all details come out a v(4) level.
This commit is contained in:
Kubernetes Submit Queue 2017-06-26 22:21:58 -07:00 committed by GitHub
commit 353633b877
1 changed files with 23 additions and 6 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

29
staging/src/k8s.io/apiserver/pkg/util/trace/trace.go
View File

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