// Copyright 2019 Yunion // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. // You may obtain a copy of the License at // // http://www.apache.org/licenses/LICENSE-2.0 // // Unless required by applicable law or agreed to in writing, software // distributed under the License is distributed on an "AS IS" BASIS, // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // See the License for the specific language governing permissions and // limitations under the License. package trace import ( "bytes" "fmt" "math/rand" "time" "yunion.io/x/log" ) type traceStep struct { stepTime time.Time msg string } type Trace struct { name string startTime time.Time steps []traceStep } func New(name string) *Trace { return &Trace{name, time.Now(), nil} } func (t *Trace) Step(msg string) { if t.steps == nil { // traces almost always have less than 6 steps, do this to avoid more than a single allocation t.steps = make([]traceStep, 0, 6) } t.steps = append(t.steps, traceStep{time.Now(), msg}) } func (t *Trace) Log() { // an explicit logging request should dump all the steps out at the higher level t.logWithStepThreshold(0) } 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 { stepDuration := step.stepTime.Sub(lastStepTime) if stepThreshold == 0 || stepDuration > stepThreshold || log.V(4) { buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] %v\n", tracenum, step.stepTime.Sub(t.startTime), stepDuration, step.msg)) } lastStepTime = step.stepTime } stepDuration := endTime.Sub(lastStepTime) if stepThreshold == 0 || stepDuration > stepThreshold || log.V(4) { buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] END\n", tracenum, endTime.Sub(t.startTime), stepDuration)) } log.Infof(buffer.String()) } func (t *Trace) LogIfLong(threshold time.Duration) { if time.Since(t.startTime) >= threshold { // 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) } } func (t *Trace) TotalTime() time.Duration { return time.Since(t.startTime) }